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