1:tocdepth: 4 2 3.. _module-pw_log_rpc: 4 5========== 6pw_log_rpc 7========== 8An RPC-based logging solution for Pigweed with log filtering and log drops 9reporting -- coming soon! 10 11.. warning:: 12 This module is under construction and might change in the future. 13 14----------- 15RPC Logging 16----------- 17 18How to Use 19========== 201. Set up RPC 21------------- 22Set up RPC for your target device. Basic deployments run RPC over a UART, with 23HDLC on top for framing. See :ref:`module-pw_rpc` for details on how to enable 24``pw_rpc``. 25 262. Set up tokenized logging (optional) 27-------------------------------------- 28Set up the :ref:`module-pw_log_tokenized` log backend. 29 303. Connect the tokenized logging handler to the MultiSink 31--------------------------------------------------------- 32Create a :ref:`MultiSink <module-pw_multisink>` instance to buffer log entries. 33Then, make the log backend handler, :c:func:`pw_log_tokenized_HandleLog`, encode 34log entries in the ``log::LogEntry`` format, and add them to the ``MultiSink``. 35 364. Create log drains and filters 37-------------------------------- 38Create an ``RpcLogDrainMap`` with one ``RpcLogDrain`` for each RPC channel used 39to stream logs. Optionally, create a ``FilterMap`` with ``Filter`` objects with 40different IDs. Provide these map to the ``LogService`` and register the latter 41with the application's RPC service. The ``RpcLogDrainMap`` provides a convenient 42way to access and maintain each ``RpcLogDrain``. Attach each ``RpcLogDrain`` to 43the ``MultiSink``. Optionally, set the ``RpcLogDrain`` callback to decide if a 44log should be kept or dropped. This callback can be ``Filter::ShouldDropLog``. 45 465. Flush the log drains in the background 47----------------------------------------- 48Depending on the product's requirements, create a thread to flush all 49``RpcLogDrain``\s or one thread per drain. The thread(s) must continuously call 50``RpcLogDrain::Flush()`` to pull entries from the ``MultiSink`` and send them to 51the log listeners. Alternatively, use ``RpcLogDrain::Trickle`` to control the 52rate of log entries streamed. Optionally, set up a callback to notify the 53thread(s) when a drain is open. 54 55Logging over RPC diagrams 56========================= 57 58Sample RPC logs request 59----------------------- 60The log listener, e.g. a computer, requests logs via RPC. The log service 61receives the request and sets up the corresponding ``RpcLogDrain`` to start the 62log stream. 63 64.. mermaid:: 65 66 graph TD 67 computer[Computer]-->pw_rpc; 68 pw_rpc-->log_service[LogService]; 69 log_service-->rpc_log_drain_pc[RpcLogDrain<br>streams to<br>computer];; 70 71Sample logging over RPC 72------------------------ 73Logs are streamed via RPC to a computer, and to another log listener. There can 74also be internal log readers, i.e. ``MultiSink::Drain``\s, attached to the 75``MultiSink``, such as a writer to persistent memory, for example. 76 77.. mermaid:: 78 79 graph TD 80 source1[Source 1]-->log_api[pw_log API]; 81 source2[Source 2]-->log_api; 82 log_api-->log_backend[Log backend]; 83 log_backend-->multisink[MultiSink]; 84 multisink-->drain[MultiSink::Drain]; 85 multisink-->rpc_log_drain_pc[RpcLogDrain<br>streams to<br>computer]; 86 multisink-->rpc_log_drain_other[RpcLogDrain<br>streams to<br>other log listener]; 87 drain-->other_consumer[Other log consumer<br>e.g. persistent memory]; 88 rpc_log_drain_pc-->pw_rpc; 89 rpc_log_drain_other-->pw_rpc; 90 pw_rpc-->computer[Computer]; 91 pw_rpc-->other_listener[Other log<br>listener]; 92 93Relation to pw_log and pw_log_tokenized 94======================================= 95``pw_log_rpc`` is often used in combination with ``pw_log`` and 96``pw_log_tokenized``. The diagram below shows the order of execution after 97invoking a ``pw_log`` macro. 98 99.. mermaid:: 100 101 flowchart TD 102 project["`**your project code**`"] 103 --> pw_log["`**pw_log** 104 *facade*`"] 105 --> token_backend["`**pw_log_tokenized** 106 *backend for pw_log*`"] 107 --> token_facade["`**pw_log_tokenized:handler** 108 *facade*`"] 109 --> custom_backend["`**your custom code** 110 *backend for pw_log_tokenized:handler*`"] 111 --> pw_log_rpc["`**pw_log_rpc**`"]; 112 113* See :ref:`docs-module-structure-facades` for an explanation of facades and 114 backends. 115* See ``pw_log_tokenized_HandleLog()`` and ``pw_log_tokenized_HandleMessageVaList()`` 116 in ``//pw_system/log_backend.cc`` for an example of how :ref:`module-pw_system` 117 implements ``your custom code (pw_log_tokenized backend)``. 118 119Components Overview 120=================== 121LogEntry and LogEntries 122----------------------- 123RPC logging uses ``LogEntry`` to encapsulate each entry's data, such as level, 124timestamp, and message. ``LogEntries`` can hold multiple instances of 125``LogEntry`` to send more data using fewer transmissions. The ``LogEntries`` has 126an optional field for the first message's sequence ID that corresponds to the 127count of each ``LogEntry`` that passes the log filter and is sent. A client can 128use this sequence ID and the number of messages in a ``LogEntries`` to figure 129out if logs were dropped during transmission. 130 131RPC log service 132--------------- 133The ``LogService`` class is an RPC service that provides a way to request a log 134stream sent via RPC and configure log filters. Thus, it helps avoid 135using a different protocol for logs and RPCs over the same interface(s). 136It requires a ``RpcLogDrainMap`` to assign stream writers and delegate the 137log stream flushing to the user's preferred method, as well as a ``FilterMap`` 138to retrieve and modify filters. The client may also stop streaming the logs by 139calling ``Cancel()`` or ``RequestCompletion()`` using the ``RawClientReader`` 140interface. Note that ``Cancel()`` may lead to dropped logs. To prevent dropped 141logs use ``RequestCompletion()`` and enable :c:macro:`PW_RPC_COMPLETION_REQUEST_CALLBACK` 142e.g. ``-DPW_RPC_COMPLETION_REQUEST_CALLBACK=1``. 143If ``PW_RPC_COMPLETION_REQUEST_CALLBACK`` is not enabled, RequestCompletion() 144call will not stop the logging stream. 145 146RpcLogDrain 147----------- 148An ``RpcLogDrain`` reads from the ``MultiSink`` instance that buffers logs, then 149packs, and sends the retrieved log entries to the log listener. One 150``RpcLogDrain`` is needed for each log listener. An ``RpcLogDrain`` needs a 151thread to continuously call ``Flush()`` to maintain the log stream. A thread can 152maintain multiple log streams, but it must not be the same thread used by the 153RPC server, to avoid blocking it. 154 155Each ``RpcLogDrain`` is identified by a known RPC channel ID and requires a 156``rpc::RawServerWriter`` to write the packed multiple log entries. This writer 157is assigned by the ``LogService::Listen`` RPC. 158 159``RpcLogDrain``\s can also be provided an open RPC writer, to constantly stream 160logs without the need to request them. This is useful in cases where the 161connection to the client is dropped silently because the log stream can continue 162when reconnected without the client requesting logs again if the error handling 163is set to ``kIgnoreWriterErrors`` otherwise the writer will be closed. 164 165An ``RpcLogDrain`` must be attached to a ``MultiSink`` containing multiple 166``log::LogEntry``\s. When ``Flush`` is called, the drain acquires the 167``rpc::RawServerWriter`` 's write buffer, grabs one ``log::LogEntry`` from the 168multisink, encodes it into a ``log::LogEntries`` stream, and repeats the process 169until the write buffer is full. Then the drain calls 170``rpc::RawServerWriter::Write`` to flush the write buffer and repeats the 171process until all the entries in the ``MultiSink`` are read or an error is 172found. 173 174The user must provide a buffer large enough for the largest entry in the 175``MultiSink`` while also accounting for the interface's Maximum Transmission 176Unit (MTU). If the ``RpcLogDrain`` finds a drop message count as it reads the 177``MultiSink`` it will insert a message in the stream with the drop message 178count in the log proto dropped optional field. The receiving end can display the 179count with the logs if desired. 180 181RpcLogDrainMap 182-------------- 183Provides a convenient way to access all or a single ``RpcLogDrain`` by its RPC 184channel ID. 185 186RpcLogDrainThread 187----------------- 188The module includes a sample thread that flushes each drain sequentially. 189``RpcLogDrainThread`` takes an encoding buffer span at construction. 190``RpcLogDrainThreadWithBuffer`` takes a template parameter for the buffer size, 191which must be large enough to fit at least one log entry. 192 193Future work might replace this with enqueueing the flush work on a work queue. 194The user can also choose to have different threads flushing individual 195``RpcLogDrain``\s with different priorities. 196 197When creating a ``RpcLogDrainThread``, the thread can be configured to 198rate limit logs by introducing a limit to how many logs can be flushed from 199each sink before a configurable sleep period begins to give the sinks time to 200handle the flushed logs. For example, if the rate limiting is configured to 2 201log bundles per flush with minimum delay of 100ms between flushes, the logging 202thread will send at most 20 log bundles per second over each sink. Log bundle 203size is dictated by the size of the encode buffer provided to the 204RpcLogDrainThread. 205 206Rate limiting is helpful in cases where transient bursts of high volumes of logs 207cause transport buffers to saturate. By rate limiting the RPC log drain, the 208transport buffers are given time to send data. As long as the average logging 209rate is significantly less than the rate limit imposed by the 210``RpcLogDrainThread``, the logging pipeline should be more resilient high 211volume log bursts. 212 213Rate limiting log drains is particularly helpful for systems that collect logs 214to a multisink in bulk when communications aren't available (e.g. collecting 215early boot logs until the logging thread starts). If a very full log buffer is 216suddenly flushed to the sinks without rate limiting, it's possible to overwhelm 217the output buffers if they don't have sufficient headroom. 218 219.. note:: 220 Introducing a logging drain rate limit will increase logging latency, but 221 usually not by much. It's important to tune the rate limit configuration to 222 ensure it doesn't unnecessarily introduce a logging bottleneck or 223 significantly increase latency. 224 225Calling ``OpenUnrequestedLogStream()`` is a convenient way to set up a log 226stream that is started without the need to receive an RCP request for logs. 227 228The ``RpcLogDrainThread`` sets up a callback for each drain, to be notified when 229a drain is opened and flushing must resume. 230 231--------- 232Log Drops 233--------- 234Unfortunately, logs can be dropped and not reach the destination. This module 235expects to cover all cases and be able to notify the user of log drops when 236possible. Logs can be dropped when 237 238- They don't pass a filter. This is the expected behavior, so filtered logs will 239 not be tracked as dropped logs. 240- The drains are too slow to keep up. In this case, the ring buffer is full of 241 undrained entries; when new logs come in, old entries are dropped. The log 242 stream will contain a ``LogEntry`` message with the number of dropped logs. 243 E.g. 244 245 Dropped 15 logs due to slow reader 246 247- There is an error creating or adding a new log entry, and the ring buffer is 248 notified that the log had to be dropped. The log stream will contain a 249 ``LogEntry`` message with the number of dropped logs. 250 E.g. 251 252 Dropped 15 logs due to slow reader 253 254- A log entry is too large for the stack buffer. The log stream will contain 255 an error message with the drop count. Provide a log buffer that fits the 256 largest entry added to the MultiSink to avoid this error. 257 E.g. 258 259 Dropped 1 log due to stack buffer too small 260 261- A log entry is too large for the outbound buffer. The log stream will contain 262 an error message with the drop count. Provide a log buffer that fits the 263 largest entry added to the MultiSink to avoid this error. 264 E.g. 265 266 Dropped 1 log due to outbound buffer too small 267 268- There are detected errors transmitting log entries. The log stream will 269 contain a ``LogEntry`` with an error message and the number of dropped logs 270 the next time the stream is flushed only if the drain's error handling is set 271 to close the stream on error. 272 E.g. 273 274 Dropped 10 logs due to writer error 275 276- There are undetected errors transmitting or receiving log entries, such as an 277 interface interruption. Clients can calculate the number of logs lost in 278 transit using the sequence ID and number of entries in each stream packet. 279 E.g. 280 281 Dropped 50 logs due to transmission error 282 283The drop count is combined when possible, and reported only when an entry, that 284passes any filters, is going to be sent. 285 286------------- 287Log Filtering 288------------- 289A ``Filter`` anywhere in the path of a ``LogEntry`` proto, for example, in the 290``PW_LOG*`` macro implementation, or in an ``RpcLogDrain`` if using RPC logging. 291The log filtering service provides read and modify access to the ``Filter``\s 292registered in the ``FilterMap``. 293 294How to Use 295========== 2961. Set up RPC 297------------- 298Set up RPC for your target device. See :ref:`module-pw_rpc` for details. 299 3002. Create ``Filter``\s 301---------------------- 302Provide each ``Filter`` with its own container for the ``FilterRules`` as big as 303the number of rules desired. These rules can be pre-poluated. 304 3053. Create a ``FilterMap`` and ``FilterService`` 306----------------------------------------------- 307Set up the ``FilterMap`` with the filters than can be modified with the 308``FilterService``. Register the service with the RPC server. 309 3104. Use RPCs to retrieve and modify filter rules 311----------------------------------------------- 312 313Components Overview 314=================== 315Filter::Rule 316------------ 317Contains a set of values that are compared against a log when set. All 318conditions must be met for the rule to be met. 319 320- ``action``: drops or keeps the log if the other conditions match. 321 The rule is ignored when inactive. 322 323- ``any_flags_set``: the condition is met if this value is 0 or the log has any 324 of these flags set. 325 326- ``level_greater_than_or_equal``: the condition is met when the log level is 327 greater than or equal to this value. 328 329- ``module_equals``: the condition is met if this byte array is empty, or the 330 log module equals the contents of this byte array. 331 332- ``thread_equals``: the condition is met if this byte array is empty or the 333 log thread equals the contents of this byte array. 334 335Filter 336------ 337Encapsulates a collection of zero or more ``Filter::Rule``\s and has 338an ID used to modify or retrieve its contents. 339 340FilterMap 341--------- 342Provides a convenient way to retrieve register filters by ID. 343 344---------------------------- 345Logging with filters example 346---------------------------- 347The following code shows a sample setup to defer the log handling to the 348``RpcLogDrainThread`` to avoid having the log streaming block at the log 349callsite. 350 351main.cc 352======= 353.. code-block:: cpp 354 355 #include "foo/log.h" 356 #include "pw_log/log.h" 357 #include "pw_thread/detached_thread.h" 358 #include "pw_thread_stl/options.h" 359 360 namespace { 361 362 void RegisterServices() { 363 pw::rpc::system_server::Server().RegisterService(foo::log::log_service); 364 pw::rpc::system_server::Server().RegisterService(foo::log::filter_service); 365 } 366 } // namespace 367 368 int main() { 369 PW_LOG_INFO("Deferred logging over RPC example"); 370 pw::rpc::system_server::Init(); 371 RegisterServices(); 372 pw::thread::DetachedThread(pw::thread::stl::Options(), foo::log::log_thread); 373 pw::rpc::system_server::Start(); 374 return 0; 375 } 376 377foo/log.cc 378========== 379Example of a log backend implementation, where logs enter the ``MultiSink`` and 380log drains and filters are set up. 381 382.. code-block:: cpp 383 384 #include "foo/log.h" 385 386 #include <array> 387 #include <cstdint> 388 389 #include "pw_chrono/system_clock.h" 390 #include "pw_log/proto_utils.h" 391 #include "pw_log_rpc/log_filter.h" 392 #include "pw_log_rpc/log_filter_map.h" 393 #include "pw_log_rpc/log_filter_service.h" 394 #include "pw_log_rpc/log_service.h" 395 #include "pw_log_rpc/rpc_log_drain.h" 396 #include "pw_log_rpc/rpc_log_drain_map.h" 397 #include "pw_log_rpc/rpc_log_drain_thread.h" 398 #include "pw_rpc_system_server/rpc_server.h" 399 #include "pw_sync/interrupt_spin_lock.h" 400 #include "pw_sync/lock_annotations.h" 401 #include "pw_sync/mutex.h" 402 403 namespace foo::log { 404 namespace { 405 constexpr size_t kLogBufferSize = 5000; 406 // Tokenized logs are typically 12-24 bytes. 407 constexpr size_t kMaxMessageSize = 32; 408 // kMaxLogEntrySize should be less than the MTU of the RPC channel output used 409 // by the provided server writer. 410 constexpr size_t kMaxLogEntrySize = 411 pw::log_rpc::RpcLogDrain::kMinEntrySizeWithoutPayload + kMaxMessageSize; 412 std::array<std::byte, kLogBufferSize> multisink_buffer; 413 414 // To save RAM, share the mutex, since drains will be managed sequentially. 415 pw::sync::Mutex shared_mutex; 416 std::array<std::byte, kMaxEntrySize> client1_buffer 417 PW_GUARDED_BY(shared_mutex); 418 std::array<std::byte, kMaxEntrySize> client2_buffer 419 PW_GUARDED_BY(shared_mutex); 420 std::array<pw::log_rpc::RpcLogDrain, 2> drains = { 421 pw::log_rpc::RpcLogDrain( 422 1, 423 client1_buffer, 424 shared_mutex, 425 RpcLogDrain::LogDrainErrorHandling::kIgnoreWriterErrors), 426 pw::log_rpc::RpcLogDrain( 427 2, 428 client2_buffer, 429 shared_mutex, 430 RpcLogDrain::LogDrainErrorHandling::kIgnoreWriterErrors), 431 }; 432 433 pw::sync::InterruptSpinLock log_encode_lock; 434 std::array<std::byte, kMaxLogEntrySize> log_encode_buffer 435 PW_GUARDED_BY(log_encode_lock); 436 437 std::array<Filter::Rule, 2> logs_to_host_filter_rules; 438 std::array<Filter::Rule, 2> logs_to_server_filter_rules{{ 439 { 440 .action = Filter::Rule::Action::kKeep, 441 .level_greater_than_or_equal = pw::log::FilterRule::Level::INFO_LEVEL, 442 }, 443 { 444 .action = Filter::Rule::Action::kDrop, 445 }, 446 }}; 447 std::array<Filter, 2> filters{ 448 Filter(pw::as_bytes(pw::span("HOST", 4)), logs_to_host_filter_rules), 449 Filter(pw::as_bytes(pw::span("WEB", 3)), logs_to_server_filter_rules), 450 }; 451 pw::log_rpc::FilterMap filter_map(filters); 452 453 extern "C" void pw_log_tokenized_HandleLog( 454 uint32_t metadata, const uint8_t message[], size_t size_bytes) { 455 int64_t timestamp = 456 pw::chrono::SystemClock::now().time_since_epoch().count(); 457 std::lock_guard lock(log_encode_lock); 458 pw::Result<pw::ConstByteSpan> encoded_log_result = 459 pw::log::EncodeTokenizedLog( 460 metadata, message, size_bytes, timestamp, log_encode_buffer); 461 462 if (!encoded_log_result.ok()) { 463 GetMultiSink().HandleDropped(); 464 return; 465 } 466 GetMultiSink().HandleEntry(encoded_log_result.value()); 467 } 468 } // namespace 469 470 pw::log_rpc::RpcLogDrainMap drain_map(drains); 471 pw::log_rpc::RpcLogDrainThread log_thread(GetMultiSink(), drain_map); 472 pw::log_rpc::LogService log_service(drain_map); 473 pw::log_rpc::FilterService filter_service(filter_map); 474 475 pw::multisink::MultiSink& GetMultiSink() { 476 static pw::multisink::MultiSink multisink(multisink_buffer); 477 return multisink; 478 } 479 } // namespace foo::log 480 481Logging in other source files 482----------------------------- 483To defer logging, other source files must simply include ``pw_log/log.h`` and 484use the :ref:`module-pw_log` APIs, as long as the source set that includes 485``foo/log.cc`` is setup as the log backend. 486 487-------------------- 488pw_log_rpc in Python 489-------------------- 490``pw_log_rpc`` provides client utilities for dealing with RPC logging. 491 492The ``LogStreamHandler`` offers APIs to start a log stream: ``start_logs``, 493to handle RPC stream errors: ``handle_log_stream_error``, and RPC stream 494completed events: ``handle_log_stream_completed``. It uses a provided 495``LogStreamDecoder`` to delegate log parsing to. 496 497Python API 498========== 499 500pw_log_rpc.rpc_log_stream 501------------------------- 502.. automodule:: pw_log_rpc.rpc_log_stream 503 :members: LogStreamHandler 504 :undoc-members: 505 :show-inheritance: 506