pw_log: Update proto - Update proto to use a single bytes field for optionally tokenized fields. - Start with a minimal set of fields, but document fields planned for future expansion. Change-Id: I5af8e65335001ffda03acc31e5077edbca9deff3 Reviewed-on: https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/47780 Commit-Queue: Wyatt Hepler <hepler@google.com> Reviewed-by: Keir Mierle <keir@google.com>
diff --git a/pw_env_setup/BUILD.gn b/pw_env_setup/BUILD.gn index 48be4eb..afd46b7 100644 --- a/pw_env_setup/BUILD.gn +++ b/pw_env_setup/BUILD.gn
@@ -35,6 +35,7 @@ "$dir_pw_doctor/py", "$dir_pw_env_setup/py", "$dir_pw_hdlc/py", + "$dir_pw_log:protos.python", "$dir_pw_log_tokenized/py", "$dir_pw_module/py", "$dir_pw_package/py",
diff --git a/pw_log/BUILD.gn b/pw_log/BUILD.gn index 2b73b97..25b5d0d 100644 --- a/pw_log/BUILD.gn +++ b/pw_log/BUILD.gn
@@ -78,8 +78,13 @@ pw_proto_library("protos") { sources = [ "log.proto" ] prefix = "pw_log/proto" + deps = [ "$dir_pw_tokenizer:proto" ] } pw_doc_group("docs") { - sources = [ "docs.rst" ] + sources = [ + "docs.rst", + "protobuf.rst", + ] + inputs = [ "log.proto" ] }
diff --git a/pw_log/docs.rst b/pw_log/docs.rst index 8924fe1..9816681 100644 --- a/pw_log/docs.rst +++ b/pw_log/docs.rst
@@ -10,6 +10,15 @@ 1. The facade (this module) which is only a macro interface layer 2. The backend, provided elsewhere, that implements the low level logging +``pw_log`` also defines a logging protobuf and RPC service for efficiently +storing and transmitting log messages. See :ref:`module-pw_log-protobuf` for +details. + +.. toctree:: + :hidden: + + protobuf + Usage examples -------------- Here is a typical usage example, showing setting the module name, and using the
diff --git a/pw_log/log.proto b/pw_log/log.proto index 2e38f42..5975ad2 100644 --- a/pw_log/log.proto +++ b/pw_log/log.proto
@@ -1,4 +1,4 @@ -// Copyright 2020 The Pigweed Authors +// Copyright 2021 The Pigweed Authors // // Licensed under the Apache License, Version 2.0 (the "License"); you may not // use this file except in compliance with the License. You may obtain a copy of @@ -12,36 +12,32 @@ // License for the specific language governing permissions and limitations under // the License. -syntax = "proto2"; +syntax = "proto3"; package pw.log; -option java_package = "pw.rpc.proto"; +import "pw_tokenizer/proto/options.proto"; + option java_outer_classname = "Log"; -// A log with a tokenized message, a string message, or dropped indicator. A -// message can be one of three types: +// A log message and metadata. Logs come in a few different forms: // // 1. A tokenized log message (recommended for production) // 2. A non-tokenized log message (good for development) // 3. A "log missed" tombstone, indicating that some logs were dropped // -// Size analysis: +// Size analysis for tokenized log messages, including each field's proto tag: // -// For tokenized log messages in the common case; including the proto tag for -// the field (so adding the fields gives the total proto message size): +// - message - 6-12 bytes, depending on number and value of arguments +// - line_level - 3 bytes; 4 bytes if line > 2048 (uncommon) +// - timestamp - 3 bytes; assuming delta encoding +// - thread_name - 6 bytes // -// - message_tokenized - 6-12 bytes, depending on # and value of arguments -// - line_level - 3 bytes; 4 bytes if line > 2048 (uncommon) -// - timestamp - 3 bytes; assuming delta encoding -// - thread_tokenized - 3 bytes -// -// Total: +// Adding the fields gives the total proto message size: // // 6-12 bytes - log // 9-15 bytes - log + level + line // 12-18 bytes - log + level + line + timestamp -// 15-21 bytes - log + level + line + timestamp + task // // An analysis of a project's log token database revealed the following // distribution of the number of arguments to log messages: @@ -58,30 +54,35 @@ // enable storing more logs in limited memory. This is why, for example, there // is no separate "DroppedLog" type, or a "TokenizedLog" and "StringLog", which // would add at least 2 extra bytes per message -// Note: Time-related fields will likely support specifying the time as a ratio -// (period) and an absolute time separate from the current delta fields. message LogEntry { - // The tokenized log message. Internally, the format has a 32-bit token - // followed by the arguments for that message. The unformatted log string - // corresponding to the token in the token database must follow this format: + // The log message, which may be tokenized. // - // file|module|message + // If tokenized logging is used, implementations may encode metadata in the + // log message rather than as separate proto fields. This reduces the size of + // the protobuf with no overhead. // - // For example: + // The standard format for encoding metadata in the log message is defined by + // the pw_log_tokenized module. The message and metadata are encoded as + // key-value pairs using ■ and ♦ as delimiters. For example: // - // ../boot/bluetooth.cc|BOOT|Bluetooth is on the fritz; error code: %d + // ■msg♦This is the log message: %d■module♦wifi■file♦../path/to/file.cc // - // Note: The level and flags are not included since level and flags are - // runtime values and so cannot be tokenized. + // See http://pigweed.dev/pw_log_tokenized for full details. When + // pw_log_tokenized is used, this metadata is automatically included as + // described. // - // Size analysis: + // The level and flags are not included since they may be runtime values and + // thus cannot always be tokenized. The line number is not included because + // line numbers change frequently and a new token is created for each line. + // + // Size analysis when tokenized: // // tag+wire = 1 byte // size = 1 byte; payload will almost always be < 127 bytes // payload = N bytes; typically 4-10 in practice // // Total: 2 + N ~= 6-12 bytes - optional bytes message_tokenized = 1; + optional bytes message = 1 [(tokenizer.format) = TOKENIZATION_OPTIONAL]; // Packed log level and line number. Structure: // @@ -93,73 +94,87 @@ // omits the line number. optional uint32 line_level = 2; - // Some log messages have flags to indicate for example assert or PII. The - // particular flags are product- and implementation-dependent. When no flags - // are present, the field is omitted entirely. + // Some log messages have flags to indicate attributes such as whether they + // are from an assert or if they contain PII. The particular flags are + // product- and implementation-dependent. optional uint32 flags = 3; - // The task or thread that created the log message. - // - // In practice, the task token and tag should be just 3 bytes, since a 14 bit - // token for the task name should be enough. - optional uint32 thread_tokenized = 4; + // Timestamps are either specified with an absolute timestamp or relative to + // the previous log entry. + oneof time { + // The absolute timestamp in implementation-defined ticks. Applications + // determine how to interpret this on the receiving end. In the simplest + // case, these ticks might be milliseconds or microseconds since boot. + // Applications could also access clock information out-of-band with a + // ClockParameters protobuf. + int64 timestamp = 4; - // Timestamp. Note: The units here are TBD and will likely require a separate - // mechanism to indicate units. This field is likely to change as we figure - // out the right strategy for timestamps in Pigweed. This is a variable-sized - // integer to enable scaling this up to a uint64 later on without impacting - // the wire format. - optional int64 timestamp = 5; + // Time since the last entry in implementation-defined ticks, as for the + // timestamp field. This enables delta encoding when batching entries + // together. + // + // Size analysis for this field including tag and varint, assuming 1 kHz + // ticks: + // + // < 127 ms gap == 127 ms == 7 bits == 2 bytes + // < 16,000 ms gap == 16 seconds == 14 bits == 3 bytes + // < 2,000,000 ms gap == 35 minutes == 21 bits == 4 bytes + // < 300,000,000 ms gap == 74 hours == 28 bits == 5 bytes + // + // Log bursts will thus consume just 2 bytes (tag + up to 127ms delta) for + // the timestamp, which is a good improvement over an absolute timestamp. + int64 time_since_last_entry = 5; + } - // Time since the last entry. Generally, one of timestamp or this field will - // be specified. This enables delta encoding when batching entries together. - // - // Size analysis for this field including tag and varint: - // - // < 127 ms gap == 127 ms == 7 bits == 2 bytes - // < 16,000 ms gap == 16 seconds == 14 bits == 3 bytes - // < 2,000,000 ms gap == 35 minutes == 21 bits == 4 bytes - // < 300,000,000 ms gap == 74 hours == 28 bits == 5 bytes - // - // Log bursts will thus consume just 2 bytes (tag + up to 127ms delta) for - // the timestamp, which is a good improvement over timestamp in many cases. - // Note: The units of this field are TBD and will likely require a separate - // mechanism to indicate units. The calculations above assume milliseconds - // and may change if the units differ. - optional int64 elapsed_time_since_last_entry = 6; - - // Fully formatted textual log message. - optional string message_string = 16; - - // For non-tokenized logging, the file name. - optional string file = 17; - - // String representation of the task that created the log message. - optional string thread_string = 18; + // The following fields are planned but will not be added until they are + // needed. Protobuf field numbers over 15 use an extra byte, so these fields + // are left out for now to avoid reserving field numbers unnecessarily. // When the log buffers are full but more logs come in, the logs are counted // and a special log message is omitted with only counts for the number of // messages dropped. The timestamp indicates the time that the "missed logs" // message was inserted into the queue. // - // Missed logs messages will only have one of the timestamp fields and these - // counters specified. - optional uint32 dropped = 19; - optional uint32 dropped_warning_or_above = 20; + // As an alternative to these fields, implementations may simply send a + // message stating the drop count. + // optional uint32 dropped = ?; + // optional uint32 dropped_warning_or_above = ?; + + // Represents the device from which the log originated. The meaning of this + // field is implementation defined + // optional uint32 source_id = ?; + + // The task or thread name that created the log message. If the log was not + // created on a thread, it should use a name appropriate to that context. + // optional bytes thread_name = ? + // [(tokenizer.format) = TOKENIZATION_OPTIONAL]; + + // The file path where this log was created, if not encoded in the message. + // optional bytes file = ? [(tokenizer.format) = TOKENIZATION_OPTIONAL]; + + // The PW_LOG_MODULE_NAME for this log message, if it is not encoded in the + // message. + // optional bytes module_name = ? + // [(tokenizer.format) = TOKENIZATION_OPTIONAL]; // Some messages are associated with trace events, which may carry additional // contextual data. This is a tuple of a data format string which could be // used by the decoder to identify the data (e.g. printf-style tokens) and the // data itself in bytes. - optional string data_format_string = 21; - optional bytes data = 22; + // optional bytes data_format = ? + // [(tokenizer.format) = TOKENIZATION_OPTIONAL]; + // optional bytes data = ?; } -message LogRequest {} +message LogRequest { + // This will include fields for configuring log filtering. +} + message LogEntries { repeated LogEntry entries = 1; } +// RPC service for accessing logs. service Logs { - rpc Get(LogRequest) returns (stream LogEntries) {} + rpc Get(LogRequest) returns (stream LogEntries); }
diff --git a/pw_log/protobuf.rst b/pw_log/protobuf.rst new file mode 100644 index 0000000..2ee7ea3 --- /dev/null +++ b/pw_log/protobuf.rst
@@ -0,0 +1,52 @@ +.. _module-pw_log-protobuf: + +------------------- +The pw_log protobuf +------------------- +``pw_log`` defines a protocol buffer for storing and transmitting log messages. +The protobuf is optimized to be maximally efficient. + +Fields +====== +The ``pw_log`` protobuf is defined in ``log.proto``. + +.. literalinclude:: log.proto + :language: protobuf + :lines: 14- + +Timestamps +---------- +Timestamps are specified in implementation-defined ticks. Ticks could be +milliseconds, microsends, or any arbitrary duration derived from the device’s +clock. + +For many applications, the timestamp field can be interpreted based on the prior +knowledge of the system. For example, ``timestamp`` might be known to be +milliseconds since boot for one core or microseconds since boot for another. + +If desired, a project could collect information about clock parameters +separately from ``pw_log``, and use that to interpret log timestamps. For +example, they may call an RPC that returns a ``pw_chrono`` ``ClockParamters`` +protobuf. The values from that could be used to interpret timestamp from that +device. + +The ``pw_log`` proto contains two timestamp fields, only one of which may be set +at a time: + +- ``timestamp`` – Absolute time when message was logged. +- ``time_since_last_entry`` – When the message was logged, relative + to the previously encoded log message. This is used when multiple log entries + are sent in a single ``LogEntries`` proto. The previous log entry must use the + same time source. If logs with multiple time sources are intermingled in a + single ``LogEntries`` proto, they must use an absolute timestamp each time the + time source changes. + +Optionally tokenized text fields +-------------------------------- +Several fields in the ``pw_log`` proto store text. Examples include ``message`` +and ``thread_name``. These fields may contain either plain or tokenized text, +either of which is represented as a single bytes field. These fields are marked +with a protocol buffer option so the ``pw_tokenizer.proto`` module can detect +and detokenize tokenized fields as appropriate. + +See :ref:`module-pw_tokenizer-proto` for details.
diff --git a/pw_log_multisink/log_queue.cc b/pw_log_multisink/log_queue.cc index 0547449..d9a6242 100644 --- a/pw_log_multisink/log_queue.cc +++ b/pw_log_multisink/log_queue.cc
@@ -34,24 +34,26 @@ uint32_t flags, uint32_t level, uint32_t line, - uint32_t thread, + uint32_t /* thread */, int64_t timestamp) { pw::protobuf::NestedEncoder nested_encoder(encode_buffer_); pw::log::LogEntry::Encoder encoder(&nested_encoder); Status status; - encoder.WriteMessageTokenized(message); + encoder.WriteMessage(message); encoder.WriteLineLevel((level & PW_LOG_LEVEL_BITMASK) | ((line << PW_LOG_LEVEL_BITS) & ~PW_LOG_LEVEL_BITMASK)); encoder.WriteFlags(flags); - encoder.WriteThreadTokenized(thread); + // TODO(prashanthsw): Update when the thread_name field is added. + // encoder.WriteThreadName(bytes::CopyInOrder(std::endian::little, &thread)); // TODO(prashanthsw): Add support for delta encoding of the timestamp. encoder.WriteTimestamp(timestamp); - if (dropped_entries_ > 0) { - encoder.WriteDropped(dropped_entries_); - } + // TODO(prashanthsw): Handle dropped messages. + // if (dropped_entries_ > 0) { + // encoder.WriteDropped(dropped_entries_); + // } ConstByteSpan log_entry; status = nested_encoder.Encode(&log_entry);
diff --git a/pw_log_multisink/log_queue_test.cc b/pw_log_multisink/log_queue_test.cc index 3d77148..9708576 100644 --- a/pw_log_multisink/log_queue_test.cc +++ b/pw_log_multisink/log_queue_test.cc
@@ -38,7 +38,7 @@ const uint32_t expected_flags, const uint32_t expected_level, const uint32_t expected_line, - const uint32_t expected_tokenized_thread, + const uint32_t /* expected_tokenized_thread */, const int64_t expected_timestamp) { ConstByteSpan log_entry_message; EXPECT_TRUE(log_decoder.Next().ok()); // preamble @@ -68,15 +68,16 @@ EXPECT_TRUE(entry_decoder.ReadUint32(&flags).ok()); EXPECT_EQ(expected_flags, flags); - uint32_t tokenized_thread; - EXPECT_TRUE(entry_decoder.Next().ok()); // tokenized_thread - EXPECT_EQ(4U, entry_decoder.FieldNumber()); - EXPECT_TRUE(entry_decoder.ReadUint32(&tokenized_thread).ok()); - EXPECT_EQ(expected_tokenized_thread, tokenized_thread); + // TODO(prashanthsw): Add thread name when supported. + // uint32_t tokenized_thread; + // EXPECT_TRUE(entry_decoder.Next().ok()); // tokenized_thread + // EXPECT_EQ(4U, entry_decoder.FieldNumber()); + // EXPECT_TRUE(entry_decoder.ReadUint32(&tokenized_thread).ok()); + // EXPECT_EQ(expected_tokenized_thread, tokenized_thread); int64_t timestamp; EXPECT_TRUE(entry_decoder.Next().ok()); // timestamp - EXPECT_EQ(5U, entry_decoder.FieldNumber()); + EXPECT_EQ(4U, entry_decoder.FieldNumber()); EXPECT_TRUE(entry_decoder.ReadInt64(×tamp).ok()); EXPECT_EQ(expected_timestamp, timestamp); }
diff --git a/pw_log_rpc/logs_rpc.cc b/pw_log_rpc/logs_rpc.cc index bf5f352..d548c84 100644 --- a/pw_log_rpc/logs_rpc.cc +++ b/pw_log_rpc/logs_rpc.cc
@@ -21,13 +21,14 @@ namespace pw::log_rpc { namespace { -Result<ConstByteSpan> GenerateDroppedEntryMessage(ByteSpan encode_buffer, - size_t dropped_entries) { - pw::protobuf::NestedEncoder nested_encoder(encode_buffer); - pw::log::LogEntry::Encoder encoder(&nested_encoder); - encoder.WriteDropped(dropped_entries); - return nested_encoder.Encode(); -} +// TODO(prashanthsw): Handle dropped messages. +// Result<ConstByteSpan> GenerateDroppedEntryMessage(ByteSpan encode_buffer, +// size_t dropped_entries) { +// pw::protobuf::NestedEncoder nested_encoder(encode_buffer); +// pw::log::LogEntry::Encoder encoder(&nested_encoder); +// encoder.WriteDropped(dropped_entries); +// return nested_encoder.Encode(); +// } } // namespace @@ -44,13 +45,14 @@ // If previous calls to flush resulted in dropped entries, generate a // dropped entry message and write it before further log messages. - if (dropped_entries_ > 0) { - ByteSpan payload = response_writer_.PayloadBuffer(); - Result dropped_log = GenerateDroppedEntryMessage(payload, dropped_entries_); - PW_TRY(dropped_log.status()); - PW_TRY(response_writer_.Write(dropped_log.value())); - dropped_entries_ = 0; - } + // TODO(prashanthsw): Handle dropped messages. + // if (dropped_entries_ > 0) { + // ByteSpan payload = response_writer_.PayloadBuffer(); + // Result dropped_log = GenerateDroppedEntryMessage(payload, + // dropped_entries_); PW_TRY(dropped_log.status()); + // PW_TRY(response_writer_.Write(dropped_log.value())); + // dropped_entries_ = 0; + // } // Write logs to the response writer. An important limitation of this // implementation is that if this RPC call fails, the logs are lost -
diff --git a/pw_log_sink/log_sink.cc b/pw_log_sink/log_sink.cc index b3ef96b..98bb086 100644 --- a/pw_log_sink/log_sink.cc +++ b/pw_log_sink/log_sink.cc
@@ -79,8 +79,7 @@ va_start(args, message); buffer.FormatVaList(message, args); va_end(args); - encoder.WriteMessageString(buffer.c_str()); - encoder.WriteThreadString(""); + encoder.WriteMessage(std::as_bytes(std::span(buffer.view()))); ConstByteSpan log_entry; Status status = nested_encoder.Encode(&log_entry);
diff --git a/pw_log_sink/log_sink_test.cc b/pw_log_sink/log_sink_test.cc index f3432c1..2fb2982 100644 --- a/pw_log_sink/log_sink_test.cc +++ b/pw_log_sink/log_sink_test.cc
@@ -35,8 +35,8 @@ EXPECT_TRUE(log_decoder.Next().ok()); // line_level - 2 EXPECT_TRUE(log_decoder.Next().ok()); // flags - 3 EXPECT_TRUE(log_decoder.Next().ok()); // timestamp - 5 - EXPECT_TRUE(log_decoder.Next().ok()); // message_string - 16 - EXPECT_EQ(16U, log_decoder.FieldNumber()); + EXPECT_TRUE(log_decoder.Next().ok()); // message - 1 + EXPECT_EQ(1u, log_decoder.FieldNumber()); EXPECT_TRUE(log_decoder.ReadString(&log_entry_message).ok()); return std::string(log_entry_message);