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