pw_system: Add log timestamp and console support
- Use time since boot as timestamp
- Remove obsolete TODOs
- Support log drop count message
- Print timestamp in a human-readable way
- Provide option for user-defined timestamp decoding
Change-Id: Ia5b30f0025877784edbce782e88e8165ed97d471
Reviewed-on: https://pigweed-review.googlesource.com/c/pigweed/pigweed/+/78281
Reviewed-by: Keir Mierle <keir@google.com>
Commit-Queue: Carlos Chinchilla <cachinchilla@google.com>
diff --git a/pw_system/BUILD.bazel b/pw_system/BUILD.bazel
index 2479bc5..443c132 100644
--- a/pw_system/BUILD.bazel
+++ b/pw_system/BUILD.bazel
@@ -42,6 +42,7 @@
":logger",
":rpc",
"//pw_bytes",
+ "//pw_chrono:system_clock",
"//pw_log",
"//pw_log:proto_utils",
"//pw_log_rpc:log_service",
@@ -120,7 +121,6 @@
],
)
-# TODO(cachinchilla): Make the target provide this.
pw_cc_library(
name = "target_io",
srcs = [
@@ -134,7 +134,6 @@
],
)
-# TODO(cachinchilla): Make the target provide this.
pw_cc_library(
name = "target_hooks",
hdrs = [
diff --git a/pw_system/BUILD.gn b/pw_system/BUILD.gn
index 1f97b71..0670e31 100644
--- a/pw_system/BUILD.gn
+++ b/pw_system/BUILD.gn
@@ -68,6 +68,7 @@
deps = [
":rpc",
"$dir_pw_bytes",
+ "$dir_pw_chrono:system_clock",
"$dir_pw_log",
"$dir_pw_log:proto_utils",
"$dir_pw_log_rpc:rpc_log_drain",
diff --git a/pw_system/CMakeLists.txt b/pw_system/CMakeLists.txt
index 2cc1baf..c06c4e9 100644
--- a/pw_system/CMakeLists.txt
+++ b/pw_system/CMakeLists.txt
@@ -31,6 +31,7 @@
PRIVATE_DEPS
"pw_system.rpc"
"pw_bytes"
+ "pw_chrono.system_clock"
"pw_log"
"pw_log.proto_utils"
"pw_log_rpc.rpc_log_drain"
diff --git a/pw_system/log.cc b/pw_system/log.cc
index ebd4a88..e0f47b4 100644
--- a/pw_system/log.cc
+++ b/pw_system/log.cc
@@ -18,6 +18,7 @@
#include <cstddef>
#include "pw_bytes/span.h"
+#include "pw_chrono/system_clock.h"
#include "pw_log/proto_utils.h"
#include "pw_log_rpc/rpc_log_drain.h"
#include "pw_log_rpc/rpc_log_drain_map.h"
@@ -60,6 +61,8 @@
log_rpc::RpcLogDrainMap drain_map(drains);
+const int64_t boot_time_count =
+ pw::chrono::SystemClock::now().time_since_epoch().count();
} // namespace
// Deferred log buffer, for storing log entries while logging_thread_ streams
@@ -79,12 +82,14 @@
return log_service;
}
+// Provides time since boot in units defined by the target's pw_chrono backend.
int64_t GetTimestamp() {
- // TODO(cachinchilla): update method to get timestamp according to target.
- return 0;
+ return pw::chrono::SystemClock::now().time_since_epoch().count() -
+ boot_time_count;
}
-// TODO (cachinchilla): Finish this!
+// Implementation for tokenized log handling. This will be optimized out for
+// devices that only use string logging.
extern "C" void pw_tokenizer_HandleEncodedMessageWithPayload(
pw_tokenizer_Payload payload, const uint8_t message[], size_t size_bytes) {
log_tokenized::Metadata metadata = payload;
diff --git a/pw_system/py/pw_system/console.py b/pw_system/py/pw_system/console.py
index 8badbee..2a676e0 100644
--- a/pw_system/py/pw_system/console.py
+++ b/pw_system/py/pw_system/console.py
@@ -32,6 +32,7 @@
"""
import argparse
+import datetime
import glob
from inspect import cleandoc
import logging
@@ -260,10 +261,18 @@
if serial_debug:
serial_impl = SerialWithLogging
+ timestamp_decoder = None
if socket_addr is None:
serial_device = serial_impl(device, baudrate, timeout=1)
read = lambda: serial_device.read(8192)
write = serial_device.write
+
+ # Overwrite decoder for serial device.
+ def milliseconds_to_string(timestamp):
+ """Parses milliseconds since boot to a human-readable string."""
+ return str(datetime.timedelta(seconds=timestamp / 1e3))[:-3]
+
+ timestamp_decoder = milliseconds_to_string
else:
try:
socket_device = SocketClientImpl(socket_addr)
@@ -278,6 +287,7 @@
write,
protos,
detokenizer,
+ timestamp_decoder=timestamp_decoder,
rpc_timeout_s=5)
_start_ipython_terminal(device_client, serial_debug, config_file)
diff --git a/pw_system/py/pw_system/device.py b/pw_system/py/pw_system/device.py
index 4b57004..bc8796a 100644
--- a/pw_system/py/pw_system/device.py
+++ b/pw_system/py/pw_system/device.py
@@ -13,10 +13,11 @@
# the License.
"""Device classes to interact with targets via RPC."""
+import datetime
import logging
from pathlib import Path
from types import ModuleType
-from typing import Any, List, Union, Optional
+from typing import Any, Callable, List, Union, Optional
from pw_hdlc.rpc import HdlcRpcClient, default_channels
import pw_log_tokenized
@@ -44,6 +45,7 @@
write,
proto_library: List[Union[ModuleType, Path]],
detokenizer: Optional[Detokenizer],
+ timestamp_decoder: Optional[Callable[[int], str]],
rpc_timeout_s=5):
self.channel_id = channel_id
self.protos = proto_library
@@ -51,6 +53,7 @@
self.logger = DEFAULT_DEVICE_LOGGER
self.logger.setLevel(logging.DEBUG) # Allow all device logs through.
+ self.timestamp_decoder = timestamp_decoder
callback_client_impl = callback_client.Impl(
default_unary_timeout_s=rpc_timeout_s,
@@ -95,8 +98,9 @@
def _log_entries_proto_parser(self, log_entries_proto: log_pb2.LogEntries):
for log_proto in log_entries_proto.entries:
- timestamp = log_proto.timestamp
- level = (log_proto.line_level & 0x7)
+ decoded_timestamp = self.decode_timestamp(log_proto.timestamp)
+ # Parse level and convert to logging module level number.
+ level = (log_proto.line_level & 0x7) * 10
if self.detokenizer:
message = str(
decode_optionally_tokenized(self.detokenizer,
@@ -104,18 +108,43 @@
else:
message = log_proto.message.decode("utf-8")
log = pw_log_tokenized.FormatStringWithMetadata(message)
- self._emit_device_log(level, '', timestamp, log.module,
- log.message, **dict(log.fields))
+ decoded_message = log.message
- def _emit_device_log(self, level: int, source_name: str, timestamp: float,
+ # Handle dropped count.
+ if log_proto.dropped:
+ level = logging.WARNING
+ decoded_timestamp = ''
+ decoded_message = f'Dropped {log_proto.dropped} log'
+ if log_proto.dropped > 1:
+ decoded_message += 's'
+
+ self._emit_device_log(level, '', decoded_timestamp, log.module,
+ decoded_message, **dict(log.fields))
+
+ def _emit_device_log(self, level: int, source_name: str, timestamp: str,
module_name: str, message: str, **metadata_fields):
+ # Fields used for console table view
fields = metadata_fields
fields['source_name'] = source_name
fields['timestamp'] = timestamp
- self.logger.log(level * 10,
- '[%s] %16.3f %s%s',
+ fields['msg'] = message
+ fields['module'] = module_name
+
+ # Format used for file or stdout logging.
+ self.logger.log(level,
+ '[%s] %s %s%s',
source_name,
timestamp,
f'{module_name} '.lstrip(),
message,
extra=dict(extra_metadata_fields=fields))
+
+ def decode_timestamp(self, timestamp: int) -> str:
+ """Decodes timestamp to a human-readable value.
+
+ Defaults to interpreting the input timestamp as nanoseconds since boot.
+ Devices can override this to match their timestamp units.
+ """
+ if self.timestamp_decoder:
+ return self.timestamp_decoder(timestamp)
+ return str(datetime.timedelta(seconds=timestamp / 1e9))[:-3]
