Merged logging with HDLC, log and ADC protos
- New device log handler: proto_over_hdlc.cc. This sends log proto
entries over serial in an HDLC frame.
- fpga_config/main.cc adds an ADCIdleTask to allow starting and
stopping adc logging when pressing enter.
- Remove log statements from interrupt handlers.
- Tweak the kFramedProtoMagicConstant to remove the `~`
character (0x7E) which is used in HDLC.
- Python changes:
- Refactor serial parsing to separate ADC proto updates from HDLC
wrapped log messages.
- Binary data functions added to help with read/write buffers and
parse varint encoding.
Bug: b/323017707
Change-Id: Ib6e1804be497b2c3d8aaf5657bd2546e07ddbe61
Reviewed-on: https://pigweed-review.googlesource.com/c/gonk/+/190510
Reviewed-by: Eric Holland <hollande@google.com>
Commit-Queue: Anthony DiGirolamo <tonymd@google.com>
Reviewed-by: Ted Pudlik <tpudlik@google.com>
Presubmit-Verified: CQ Bot Account <pigweed-scoped@luci-project-accounts.iam.gserviceaccount.com>
diff --git a/README.md b/README.md
index 02a38fc..af729c0 100644
--- a/README.md
+++ b/README.md
@@ -89,7 +89,20 @@
1. Write an FPGA bitstream with the `write_fpga.py` script:
```sh
- python ./tools/gonk_tools/write_fpga.py --bitstream-file ./out/gn/obj/fpga/toplevel/toplevel.bin
+ python ./tools/gonk_tools/write_fpga.py \
+ --bitstream-file ./out/gn/obj/fpga/toplevel/toplevel.bin
+ --database ./out/gn/arduino_size_optimized/obj/applications/fpga_config/bin/fpga_config.elf \
+ --log-to-stderr
+ ```
+
+ You can redirect host and device logs to separate files with:
+
+ ```sh
+ python ./tools/gonk_tools/write_fpga.py \
+ --bitstream-file ./out/gn/obj/fpga/toplevel/toplevel.bin
+ --database ./out/gn/arduino_size_optimized/obj/applications/fpga_config/bin/fpga_config.elf \
+ --host-logfile gonk-host-logs.txt \
+ --device-logfile gonk-device-logs.txt
```
### Alternative: Flash with BlackMagic Probe
diff --git a/applications/fpga_config/main.cc b/applications/fpga_config/main.cc
index 6492d01..1699362 100644
--- a/applications/fpga_config/main.cc
+++ b/applications/fpga_config/main.cc
@@ -51,15 +51,14 @@
Adc fpga_adc = Adc(Serial, pin_config.fpga_spi, /*fpga_spi_baudrate=*/7500000,
FpgaDspiCS, FpgaIoMode, FpgaIoReset, FpgaIoValid);
-void ice40_done_rising_isr() { PW_LOG_DEBUG("ICE40 Done: HIGH"); }
-
void (*current_task)();
} // namespace
void IdleTask();
void FpgaConfigTask();
-void ADCTask();
+void ADCIdleTask();
+void ADCReadTask();
void IdleTask() {
static uint32_t last_update = millis();
@@ -94,7 +93,51 @@
}
}
-void ADCTask() {
+void ADCIdleTask() {
+ static uint32_t last_update = millis();
+ static uint32_t this_update = millis();
+ static uint16_t update_count = 0;
+
+ this_update = millis();
+
+ if (Serial.available()) {
+ int data_in = Serial.read();
+ if (data_in == '\n') {
+ PW_LOG_INFO("Starting ADC Continuous Reads.");
+ fpga_adc.SetContinuousReadMode();
+ current_task = &ADCReadTask;
+ }
+ }
+
+ // Output an idle state heartbeat message each second.
+ if (this_update > last_update + 1000) {
+ PW_LOG_INFO("ADC Idle");
+
+ last_update = this_update;
+ update_count = (update_count + 1) % UINT16_MAX;
+
+ // Toggle status LED each loop.
+ if (update_count % 2 == 0) {
+ digitalWrite(StatusLed, HIGH);
+ } else {
+ digitalWrite(StatusLed, LOW);
+ }
+ }
+}
+
+void ADCReadTask() {
+ // Check for serial input.
+ if (Serial.available()) {
+ int data_in = Serial.read();
+ // Press enter to stop.
+ if (data_in == '\n') {
+ PW_LOG_INFO("Stopping ADC Continuous Reads.");
+ fpga_adc.SetReadWriteMode();
+ current_task = &ADCIdleTask;
+ return;
+ }
+ }
+
pw::Status update_result = fpga_adc.UpdateContinuousMeasurements();
if (!update_result.ok()) {
PW_LOG_ERROR("UpdateContinuousMeasurements() failed");
@@ -121,7 +164,7 @@
auto result = fpga_control.StartConfig();
if (result.ok()) {
// FPGA has been configure successfully.
- current_task = &ADCTask;
+ current_task = &ADCReadTask;
// Check if SPI flash is readable.
CheckSpiFlash();
// Init ADCs
@@ -130,7 +173,6 @@
// Select the first five ADC channels.
fpga_adc.SelectContinuousReadAdcs(0b11111);
- PW_LOG_INFO("Switching to ADC binary log");
fpga_adc.SetContinuousReadMode();
} else {
PW_LOG_INFO("Restarting FPGA Config.");
@@ -139,10 +181,6 @@
}
int main() {
- // Debug interrupt to watch when ICE40Done goes high.
- attachInterrupt(/*pin=*/ICE40Done, /*callback=*/&ice40_done_rising_isr,
- /*mode=*/HIGH);
-
pin_config.Init();
pin_config.InitFpgaPins();
delay(500);
diff --git a/lib/adc/adc.cc b/lib/adc/adc.cc
index 40ed56e..b95516b 100644
--- a/lib/adc/adc.cc
+++ b/lib/adc/adc.cc
@@ -24,10 +24,7 @@
volatile uint8_t fpga_valid_pulse_ = 0;
-void io_valid_rising_isr() {
- fpga_valid_pulse_ = 1;
- PW_LOG_DEBUG("IO Valid: HIGH");
-}
+void io_valid_rising_isr() { fpga_valid_pulse_ = 1; }
void ClearValidPulse() { fpga_valid_pulse_ = 0; }
diff --git a/lib/adc/public/gonk/adc.h b/lib/adc/public/gonk/adc.h
index 9607fd6..9ab9ed0 100644
--- a/lib/adc/public/gonk/adc.h
+++ b/lib/adc/public/gonk/adc.h
@@ -14,7 +14,7 @@
namespace gonk::adc {
-const uint32_t kFramedProtoMagicConstant = 0x7EAABB99;
+const uint32_t kFramedProtoMagicConstant = 0x7DAABB99;
const uint8_t kTotalAdcCount = 11;
const uint8_t kMaxStreamingAdcCount = 11;
diff --git a/lib/log_backends/BUILD.gn b/lib/log_backends/BUILD.gn
new file mode 100644
index 0000000..8a07725
--- /dev/null
+++ b/lib/log_backends/BUILD.gn
@@ -0,0 +1,28 @@
+# Copyright 2024 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
+# the License at
+#
+# https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations under
+# the License.
+
+import("//build_overrides/pigweed.gni")
+
+import("$dir_pw_build/target_types.gni")
+
+pw_source_set("proto_over_hdlc") {
+ sources = [ "proto_over_hdlc.cc" ]
+ deps = [
+ "$dir_pw_hdlc:encoder",
+ "$dir_pw_log:proto_utils",
+ "$dir_pw_log_tokenized:handler.facade",
+ "$dir_pw_stream:sys_io_stream",
+ dir_pw_span,
+ ]
+}
diff --git a/lib/log_backends/proto_over_hdlc.cc b/lib/log_backends/proto_over_hdlc.cc
new file mode 100644
index 0000000..87867fb
--- /dev/null
+++ b/lib/log_backends/proto_over_hdlc.cc
@@ -0,0 +1,63 @@
+// Copyright 2024 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
+// the License at
+//
+// https://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+// WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+// License for the specific language governing permissions and limitations under
+// the License.
+
+// This function serves as a backend for pw_tokenizer / pw_log_tokenized that
+// encodes tokenized logs as Base64 and writes them using HDLC.
+
+#include "pw_bytes/endian.h"
+#include "pw_bytes/span.h"
+#include "pw_hdlc/encoder.h"
+#include "pw_log/proto_utils.h"
+#include "pw_log_tokenized/handler.h"
+#include "pw_log_tokenized/metadata.h"
+#include "pw_span/span.h"
+#include "pw_stream/sys_io_stream.h"
+#include "pw_string/string.h"
+#include "pw_tokenizer/tokenize.h"
+
+namespace pw::log_tokenized {
+namespace {
+
+inline constexpr int kLogProtoHdlcAddress = 1;
+std::array<std::byte, 512> log_encode_buffer;
+
+stream::SysIoWriter writer;
+
+// Create a log encode failure message in place of a proper crash handler.
+constexpr uint32_t kLogEncodeFailToken =
+ PW_TOKENIZE_STRING("pw::log::EncodeTokenizedLog failed");
+constexpr std::array<std::byte, 4> kLogEncodeFailBytes =
+ pw::bytes::CopyInOrder(pw::endian::little, kLogEncodeFailToken);
+
+} // namespace
+
+// Proto encodes tokenized logs and writes them to pw::sys_io as HDLC frames.
+extern "C" void pw_log_tokenized_HandleLog(uint32_t payload,
+ const uint8_t log_buffer[],
+ size_t size_bytes) {
+ pw::log_tokenized::Metadata metadata = payload;
+
+ Result<ConstByteSpan> encoded_log_result = pw::log::EncodeTokenizedLog(
+ metadata, log_buffer, size_bytes, /*timestamp=*/0, log_encode_buffer);
+
+ if (encoded_log_result.ok()) {
+ // HDLC-encode the encoded proto via a SysIoWriter.
+ hdlc::WriteUIFrame(kLogProtoHdlcAddress, encoded_log_result.value(),
+ writer);
+ } else {
+ hdlc::WriteUIFrame(kLogProtoHdlcAddress, kLogEncodeFailBytes, writer);
+ }
+}
+
+} // namespace pw::log_tokenized
diff --git a/targets/stm32f730r8tx_arduino/target_toolchains.gni b/targets/stm32f730r8tx_arduino/target_toolchains.gni
index b0fe0e2..15c756d 100644
--- a/targets/stm32f730r8tx_arduino/target_toolchains.gni
+++ b/targets/stm32f730r8tx_arduino/target_toolchains.gni
@@ -44,7 +44,8 @@
# Facade backends
pw_assert_BACKEND = dir_pw_assert_log
- pw_log_BACKEND = dir_pw_log_basic
+ pw_log_BACKEND = dir_pw_log_tokenized
+ pw_log_tokenized_HANDLER_BACKEND = "//lib/log_backends:proto_over_hdlc"
pw_sync_INTERRUPT_SPIN_LOCK_BACKEND =
"$dir_pw_sync_baremetal:interrupt_spin_lock"
pw_sync_MUTEX_BACKEND = "$dir_pw_sync_baremetal:mutex"
diff --git a/tools/BUILD.gn b/tools/BUILD.gn
index 3b8c8f1..d7027cd 100644
--- a/tools/BUILD.gn
+++ b/tools/BUILD.gn
@@ -23,17 +23,25 @@
]
sources = [
"gonk_tools/__init__.py",
+ "gonk_tools/binary_handler.py",
"gonk_tools/build_project.py",
"gonk_tools/find_serial_port.py",
"gonk_tools/flash.py",
+ "gonk_tools/gonk_log_stream.py",
"gonk_tools/presubmit_checks.py",
"gonk_tools/write_fpga.py",
]
+ tests = [ "binary_handler_test.py" ]
python_deps = [
"$dir_pw_arduino_build/py",
"$dir_pw_build/py",
"$dir_pw_cli/py",
+ "$dir_pw_console/py",
+ "$dir_pw_hdlc/py",
+ "$dir_pw_log/py",
+ "$dir_pw_log_tokenized/py",
"$dir_pw_presubmit/py",
+ "$dir_pw_tokenizer/py",
"//lib/adc:protos.python",
]
pylintrc = "$dir_pigweed/.pylintrc"
diff --git a/tools/binary_handler_test.py b/tools/binary_handler_test.py
new file mode 100644
index 0000000..c89b1f2
--- /dev/null
+++ b/tools/binary_handler_test.py
@@ -0,0 +1,175 @@
+# Copyright 2024 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
+# the License at
+#
+# https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations under
+# the License.
+"""Tests for gonk binary data"""
+
+import unittest
+
+from gonk_tools.binary_handler import (
+ BIN_LOG_SYNC_START_BYTES,
+ BIN_LOG_SYNC_START_STR,
+ BytearrayLoop,
+ decode_one_varint,
+)
+from gonk_tools.gonk_log_stream import GonkLogStream
+
+# pylint: disable=line-too-long
+_SAMPLE_ENCODED_LOGS = [
+ b'~$llsrqA==E\xc4\xe2\x93~',
+ b'~$w4ZyKAI=0\x8f\xbf!~',
+ b'~$w4ZyKAQ=i\xa4\xa3~',
+ b'~$w4ZyKAY=a\x9d}]k~',
+ b'~$w4ZyKAg=\x86\xb8*~',
+ b'~$YNjZuQ==X\xb2\xc1@~',
+ b'~$J+09dYBA\xb2\xf8^~',
+]
+
+_SAMPLE_PROTO_PACKETS = [
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}122310d380ef020a04080010030a04080010020a040800104e0a040845104f0a0408001002'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}122110bf010a04080010030a04080010020a040800104e0a04080010020a040800104f'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}122a10b9010a04080010030a04080010020a04080010030a04080010020a0d080010b6ffffffffffffffff01'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}122a10d1010a04080010030a04080010020a04084710030a0d080010b7ffffffffffffffff010a0408001002'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}123310df010a04080010030a0d080010b6ffffffffffffffff010a04080010030a0d080010b7ffffffffffffffff010a0408001002'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}127210ffffffff0f0a04080010030a04080010020a04080010030a04080010020a04080010020a0d080010b7ffffffffffffffff010a0d080010b7ffffffffffffffff010a04084710020a04084710030a04080010030a04080010020a1608ffffffffffffffffff0110ffffffffffffffffff01'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}127b10ffffffff0f0a04080010030a04080010020a04080010030a04080010020a0d080010b6ffffffffffffffff010a0d080010b7ffffffffffffffff010a0d080010b7ffffffffffffffff010a04080010020a04080010030a04080010030a04080010020a1608ffffffffffffffffff0110ffffffffffffffffff01'
+ ),
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}127210ffffffff0f0a04080010030a04080010020a04080010030a04084510020a04080010020a04080010020a0d080010b7ffffffffffffffff010a04084610020a04080010030a04080010030a0d084810b6ffffffffffffffff010a1608ffffffffffffffffff0110ffffffffffffffffff01'
+ ),
+]
+_SAMPLE_LONG_PROTO_PACKETS = [
+ # Artificially increased size > 127 (uses two bytes for the packet size varint)
+ bytes.fromhex(
+ f'{BIN_LOG_SYNC_START_STR}12F20110ffffffff0f0a04080010030a04080010020a04080010030a04084510020a04080010020a04080010020a0d080010b7ffffffffffffffff010a04084610020a04080010030a04080010030a0d084810b6ffffffffffffffff010a1608ffffffffffffffffff0110ffffffffffffffffff0110ffffffff0f0a04080010030a04080010020a04080010030a04084510020a04080010020a04080010020a0d080010b7ffffffffffffffff010a04084610020a04080010030a04080010030a0d084810b6ffffffffffffffff010a1608ffffffffffffffffff0110ffffffffffffffffff01ffffffffffffffffff01ffffffff'
+ ),
+]
+
+
+# pylint: enable=line-too-long
+class TestHandleBinaryData(unittest.TestCase):
+ """Tests for binary log data."""
+ def setUp(self):
+ # Show large diffs
+ self.maxDiff = None # pylint: disable=invalid-name
+
+ def test_gonk_stream_write(self) -> None:
+ """Test GonkLogStream.write handles protos and logs correctly."""
+ log_data = b''.join([
+ _SAMPLE_ENCODED_LOGS[1],
+ ])
+ proto_data1 = _SAMPLE_LONG_PROTO_PACKETS[0]
+
+ gl = GonkLogStream()
+ gl.write(log_data)
+ # No proto bytes yet.
+ self.assertEqual(None, gl.remaining_proto_bytes)
+
+ gl.write(proto_data1 + log_data)
+ # One log data section should be in the log_buffer
+ self.assertEqual(log_data, gl.log_buffer.getbuffer())
+ # One proto packet should be consumed.
+ self.assertEqual(None, gl.remaining_proto_bytes)
+ self.assertEqual(log_data, gl.input_buffer.getbuffer())
+
+ # Write a third log
+ gl.write(log_data)
+ # Log buffer should have 3 logs
+ self.assertEqual(log_data * 3, gl.log_buffer.getbuffer())
+ # Input buffer now empty
+ self.assertEqual(b'', gl.input_buffer.getbuffer())
+
+ def test_read_until(self) -> None:
+ """Test BytearrayLoop.read_until."""
+ log_data = b''.join([
+ _SAMPLE_ENCODED_LOGS[1],
+ _SAMPLE_ENCODED_LOGS[2],
+ ])
+ proto_data = b''.join([
+ _SAMPLE_PROTO_PACKETS[0],
+ _SAMPLE_PROTO_PACKETS[1],
+ ])
+
+ with self.subTest(
+ msg="Matching sub sequence exists; read until that."):
+ merged_data = log_data + proto_data
+ bl = BytearrayLoop(merged_data)
+ self.assertEqual(log_data, bl.read_until(BIN_LOG_SYNC_START_BYTES))
+ self.assertEqual(proto_data, bl.getbuffer())
+
+ with self.subTest(
+ msg="No matching sub sequence exists; read all data."):
+ bl = BytearrayLoop(log_data)
+ self.assertEqual(log_data, bl.read_until(BIN_LOG_SYNC_START_BYTES))
+ # Remaining buffer should be empty
+ self.assertEqual(b'', bl.getbuffer())
+
+ with self.subTest(
+ msg="Matching sub sequence at the start, read nothing."):
+ bl = BytearrayLoop(proto_data)
+ self.assertEqual(b'', bl.read_until(BIN_LOG_SYNC_START_BYTES))
+ # Remaining buffer should be full
+ self.assertEqual(proto_data, bl.getbuffer())
+
+ with self.subTest(msg="Subsequence is longer than the buffer."):
+ # Searching for a subsequece longer than the buffer should return an
+ # empty result.
+ too_short_buffer = BytearrayLoop(bytes.fromhex('abc123'))
+ self.assertEqual(
+ b'',
+ too_short_buffer.read_until(bytes.fromhex('abc123456789')))
+
+ def test_proto_packet_length(self) -> None:
+ """Test decode_one_varint on remaining protobuf lengths."""
+ for packet in _SAMPLE_PROTO_PACKETS:
+ bl = BytearrayLoop()
+
+ bl.write(packet)
+ self.assertEqual(packet, bl.getbuffer())
+
+ original_size = len(packet)
+ packet_size = original_size
+
+ self.assertEqual(BIN_LOG_SYNC_START_BYTES, bl.peek(5))
+ # Read magic bytes fixed32 tag + 4 bytes.
+ magic_start = bl.read(5)
+ self.assertEqual(BIN_LOG_SYNC_START_BYTES, magic_start)
+ packet_size -= 5
+
+ # Read the tag.
+ _tag = bl.read(1)
+ packet_size -= 1
+
+ # Read the varint with the remaining packet size.
+ original_size = len(bl.getbuffer())
+ decoded_remaining_size = decode_one_varint(bl)
+ # Subtract bytes used by the varint
+ packet_size -= original_size - len(bl.getbuffer())
+
+ self.assertEqual(decoded_remaining_size, packet_size)
+
+
+if __name__ == '__main__':
+ unittest.main()
diff --git a/tools/gonk_tools/binary_handler.py b/tools/gonk_tools/binary_handler.py
new file mode 100644
index 0000000..ead60b7
--- /dev/null
+++ b/tools/gonk_tools/binary_handler.py
@@ -0,0 +1,97 @@
+# Copyright 2024 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
+# the License at
+#
+# https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations under
+# the License.
+"""Binary log data functions."""
+
+import io
+import threading
+from typing import Union
+
+BIN_LOG_SYNC_START_STR = '0d99bbaa7d'
+BIN_LOG_SYNC_START_BYTES = bytes.fromhex(BIN_LOG_SYNC_START_STR)
+
+
+class BytearrayLoop:
+ """A bytearray reader writer.
+
+ Reads occur from the front of the buffer and remove data. Writes append to
+ the end of the buffer.
+ """
+ def __init__(self, data: bytes = b''):
+ self.buffer = bytearray(data)
+ self.lock = threading.Lock()
+
+ def read(self, size: int = -1) -> bytearray:
+ """Read bytes from the start of the buffer."""
+ data = b''
+ with self.lock:
+ if size < 0:
+ size = len(self.buffer)
+ data = self.buffer[:size]
+ # Delete the data we just fetched
+ self.buffer[:size] = b''
+ return data
+
+ def write(self, data: bytes) -> None:
+ """Write bytes to the end of the buffer."""
+ with self.lock:
+ self.buffer.extend(data)
+
+ def peek(self, size: int = 0) -> bytearray:
+ """Peek into bytes from the start."""
+ return self.buffer[:size]
+
+ def __len__(self) -> int:
+ return len(self.buffer)
+
+ def getbuffer(self) -> bytearray:
+ """Return the whole buffer."""
+ return self.buffer
+
+ def read_until(self, sub_sequece: bytes) -> bytearray:
+ """Pop all data from the buffer until a subsequence is found."""
+ # Return nothing if the buffer is smaller than the provided subsequence.
+ if len(sub_sequece) > len(self.buffer):
+ return bytearray()
+ position = self.buffer.find(sub_sequece)
+ # If no subsequece is found, read all data.
+ if position < 0:
+ return self.read()
+ return self.read(position)
+
+
+_RawIo = Union[io.RawIOBase, BytearrayLoop]
+
+
+def decode_one_varint(stream: _RawIo) -> int:
+ """Read a single varint from a byte stream."""
+ # Track the amount shifted.
+ shift = 0
+ # Resulting varint.
+ result = 0
+ while True:
+ # Get one byte
+ b = stream.read(1)
+ if not b:
+ break
+ # Read as an integer. Note: byte order is little endian but we are only
+ # reading one byte at a time.
+ i = int.from_bytes(b, byteorder='little')
+ # Shift first 7 bits from this byte into the result.
+ result |= (i & 0x7f) << shift
+ shift += 7
+ # Stop if the highest bit is not set.
+ if not i & 0x80:
+ break
+
+ return result
diff --git a/tools/gonk_tools/gonk_log_stream.py b/tools/gonk_tools/gonk_log_stream.py
new file mode 100644
index 0000000..6709037
--- /dev/null
+++ b/tools/gonk_tools/gonk_log_stream.py
@@ -0,0 +1,220 @@
+# Copyright 2024 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
+# the License at
+#
+# https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations under
+# the License.
+"""Gonk log stream handler."""
+
+from datetime import datetime
+import logging
+import time
+from typing import Optional
+
+from google.protobuf.message import DecodeError
+from pw_hdlc.decode import FrameDecoder
+from pw_log.log_decoder import LogStreamDecoder
+from pw_log.proto import log_pb2
+from pw_tokenizer import detokenize
+import pw_log.log_decoder
+
+from gonk_adc.adc_measurement_pb2 import FramedProto
+from gonk_tools.binary_handler import (
+ BIN_LOG_SYNC_START_BYTES,
+ BytearrayLoop,
+)
+
+_LOG = logging.getLogger('host')
+_DEVICE_LOG = logging.getLogger('gonk')
+
+
+def emit_python_log(log: pw_log.log_decoder.Log) -> None:
+ log.metadata_fields['module'] = log.module_name
+ log.metadata_fields['source_name'] = log.source_name
+ log.metadata_fields['timestamp'] = log.timestamp
+ log.metadata_fields['msg'] = log.message
+ log.metadata_fields['file'] = log.file_and_line
+
+ _DEVICE_LOG.log(
+ log.level,
+ '%s -- %s',
+ log.message,
+ log.file_and_line,
+ extra=dict(extra_metadata_fields=log.metadata_fields),
+ )
+
+
+class GonkLogStream:
+ """Handle incoming serial data from Gonk."""
+
+ # pylint: disable=too-many-instance-attributes
+ def __init__(
+ self,
+ detokenizer: Optional[detokenize.Detokenizer] = None,
+ adc_time_format: str = '%Y%m%d %H:%M:%S.%f',
+ ) -> None:
+ self.detokenizer = detokenizer
+ self.log_decoder: Optional[LogStreamDecoder] = None
+ if self.detokenizer:
+ self.log_decoder = LogStreamDecoder(
+ decoded_log_handler=emit_python_log, detokenizer=detokenizer)
+ self.input_buffer = BytearrayLoop()
+ self.log_buffer = BytearrayLoop()
+ self.frame_decoder = FrameDecoder()
+ self.adc_time_format = adc_time_format
+
+ self.remaining_proto_bytes: Optional[int] = None
+
+ self.proto_update_count: int = 0
+ self.proto_update_time = time.monotonic()
+
+ def _maybe_log_update_rate(self) -> None:
+ self.proto_update_count += 1
+ current_time = time.monotonic()
+ if current_time > self.proto_update_time + 1:
+ _LOG.info('ADC updates/second: %d', self.proto_update_count)
+ self.proto_update_count = 0
+ self.proto_update_time = current_time
+
+ def write(self, data: bytes) -> None:
+ """Write data and separate protobuf data from logs."""
+ self.input_buffer.write(data)
+
+ logdata = self.input_buffer.read_until(BIN_LOG_SYNC_START_BYTES)
+ if logdata:
+ self.log_buffer.write(logdata)
+
+ self._handle_log_data()
+ self._handle_proto_packets()
+
+ def _next_proto_packet_size(self) -> Optional[int]:
+ packet_size: Optional[int] = None
+
+ required_bytes = 8
+ # Expected bytes:
+ # 1: fixed32 tag
+ # 4: sync start value bytes
+ # 1: varint tag
+ # 2: varint value (one to two bytes)
+ head_bytes = self.input_buffer.peek(required_bytes)
+ if len(
+ head_bytes
+ ) < required_bytes or BIN_LOG_SYNC_START_BYTES not in head_bytes:
+ return packet_size
+
+ _sync_start_bytes = head_bytes[:5]
+ _varint_tag = head_bytes[5:6]
+ # Decode 1-2 varint bytes.
+ varint_byte1 = head_bytes[6:7]
+ varint_byte2 = head_bytes[7:8]
+ i = int.from_bytes(varint_byte1)
+ packet_size = i & 0x7f
+ if (i & 0x80) == 0x80:
+ # Decode the extra varint byte
+ packet_size |= (int.from_bytes(varint_byte2) & 0x7f) << 7
+ else:
+ # Extra varint byte value not used.
+ required_bytes -= 1
+
+ return required_bytes + packet_size
+
+ def _handle_log_data(self) -> None:
+ log_data = self.log_buffer.read()
+ for frame in self.frame_decoder.process(log_data):
+ if not frame.ok():
+ _LOG.warning(
+ 'Failed to decode frame: %s; discarded %d bytes',
+ frame,
+ len(frame.raw_encoded),
+ )
+ # Save this data back to the log_buffer
+ self.log_buffer.write(frame.raw_encoded)
+ continue
+
+ if not self.log_decoder:
+ _DEVICE_LOG.info('%s', frame)
+ continue
+
+ log_entry = log_pb2.LogEntry()
+ try:
+ log_entry.ParseFromString(frame.data)
+ except DecodeError:
+ # Try to detokenize the frame data and log the failure.
+ detokenized_text = ''
+ if self.detokenizer:
+ detokenized_text = str(
+ self.detokenizer.detokenize(frame.data))
+ if detokenized_text:
+ _LOG.warning('Failed to parse log proto "%s" %s',
+ detokenized_text, frame)
+ else:
+ _LOG.warning('Failed to parse log proto %s', frame)
+ continue
+
+ log = self.log_decoder.parse_log_entry_proto(log_entry)
+ emit_python_log(log)
+
+ def _handle_proto_packets(self) -> None:
+ # If no proto has been found, check for a new one.
+ if self.remaining_proto_bytes is None:
+ self.remaining_proto_bytes = self._next_proto_packet_size()
+
+ # If a proto was found and bytes are pending.
+ if (self.remaining_proto_bytes is not None
+ and self.remaining_proto_bytes > 0):
+
+ # If the remaining bytes are available in the buffer.
+ if self.remaining_proto_bytes == len(
+ self.input_buffer.peek(self.remaining_proto_bytes)):
+ # Pop the proto
+ proto_bytes = bytes(
+ self.input_buffer.read(self.remaining_proto_bytes))
+ # All bytes consumed
+ self.remaining_proto_bytes = None
+ self._parse_and_log_adc_proto(proto_bytes)
+ self._maybe_log_update_rate()
+
+ def _parse_and_log_adc_proto(self, proto_bytes: bytes) -> None:
+ """Parse an ADC proto message and log."""
+ framed_proto = FramedProto()
+
+ try:
+ framed_proto.ParseFromString(proto_bytes)
+ except DecodeError:
+ _LOG.error('ADC FramedProto.DecodeError: %s', proto_bytes.hex())
+ return
+
+ host_time = datetime.now().strftime(self.adc_time_format)
+ packet_size = len(proto_bytes)
+ delta_micros = framed_proto.payload.timestamp
+
+ vbus_values = []
+ vshunt_values = []
+ for adc_measure in framed_proto.payload.adc_measurements:
+ vbus_values.append(adc_measure.vbus_value)
+ vshunt_values.append(adc_measure.vshunt_value)
+
+ _DEVICE_LOG.info(
+ 'host_time: %s size: %s delta_microseconds: %s '
+ 'vbus: %s vshunt: %s',
+ host_time,
+ str(packet_size),
+ str(delta_micros),
+ ','.join(str(value) for value in vshunt_values),
+ ','.join(str(value) for value in vbus_values),
+ extra=dict(
+ extra_metadata_fields={
+ 'host_time': host_time,
+ 'packet_size': packet_size,
+ 'delta_micros': delta_micros,
+ 'vbus_values': vbus_values,
+ 'vshunt_values': vshunt_values,
+ }),
+ )
diff --git a/tools/gonk_tools/write_fpga.py b/tools/gonk_tools/write_fpga.py
index 9699bcd..fd879f7 100644
--- a/tools/gonk_tools/write_fpga.py
+++ b/tools/gonk_tools/write_fpga.py
@@ -14,23 +14,34 @@
"""Write a binary over serial to provision the Gonk FPGA."""
import argparse
-from datetime import datetime
import importlib.resources
from itertools import islice
+import logging
import operator
from pathlib import Path
import sys
import time
-from typing import Optional
+from typing import Optional, Iterable
import serial
from serial import Serial
from serial.tools.list_ports import comports
from serial.tools.miniterm import Miniterm, Transform
-from google.protobuf.message import DecodeError
+from pw_cli import log as pw_cli_log
+from pw_console import python_logging
import pw_cli.color
-from gonk_adc.adc_measurement_pb2 import FramedProto
+from pw_tokenizer import (
+ database as pw_tokenizer_database,
+ detokenize,
+ tokens,
+)
+
+from gonk_tools.gonk_log_stream import GonkLogStream
+
+_ROOT_LOG = logging.getLogger()
+_LOG = logging.getLogger('host')
+_DEVICE_LOG = logging.getLogger('gonk')
_COLOR = pw_cli.color.colors()
@@ -49,7 +60,22 @@
def _parse_args():
- parser = argparse.ArgumentParser(description=__doc__)
+ parser = argparse.ArgumentParser(
+ description=__doc__,
+ formatter_class=argparse.RawDescriptionHelpFormatter,
+ )
+ parser.add_argument(
+ '--databases',
+ metavar='elf_or_token_database',
+ action=pw_tokenizer_database.LoadTokenDatabases,
+ nargs='+',
+ help=('ELF or token database files from which to read strings and '
+ 'tokens. For ELF files, the tokenization domain to read from '
+ 'may specified after the path as #domain_name (e.g. '
+ 'foo.elf#TEST_DOMAIN). Unless specified, only the default '
+ 'domain ("") is read from ELF files; .* reads all domains. '
+ 'Globs are expanded to compatible database files.'),
+ )
parser.add_argument(
'-p',
'--port',
@@ -78,6 +104,49 @@
help=('FPGA Bitstream file. Can be a filesystem path or "DEFAULT" to '
'use a Gonk Python tools bundled binary file.'),
)
+ parser.add_argument(
+ '--logfile',
+ type=Path,
+ default=Path('gonk-logs.txt'),
+ help=('Default log file. This will contain host side '
+ 'log messages only unles the '
+ '--merge-device-and-host-logs argument is used.'),
+ )
+ parser.add_argument(
+ '--merge-device-and-host-logs',
+ action='store_true',
+ help=('Include device logs in the default --logfile.'
+ 'These are normally shown in a separate device '
+ 'only log file.'),
+ )
+ parser.add_argument(
+ '--log-colors',
+ action=argparse.BooleanOptionalAction,
+ help=('Colors in log messages.'),
+ )
+ parser.add_argument(
+ '--log-to-stderr',
+ action='store_true',
+ help=('Log to STDERR'),
+ )
+ parser.add_argument(
+ '--host-logfile',
+ type=Path,
+ help=('Additional host only log file. Normally all logs in the '
+ 'default logfile are host only.'),
+ )
+ parser.add_argument(
+ '--device-logfile',
+ type=Path,
+ default=Path('gonk-device-logs.txt'),
+ help='Device only log file.',
+ )
+ parser.add_argument(
+ '--json-logfile',
+ help='Device only JSON formatted log file.',
+ type=Path,
+ )
+
return parser.parse_args()
@@ -110,9 +179,6 @@
FILE_START_BYTES = bytes.fromhex(FILE_START_STR)
SYNC_START_BYTES = bytes.fromhex(SYNC_START_STR)
-BIN_LOG_SYNC_START_STR = '0d 99 bb aa 7e'
-BIN_LOG_SYNC_START_BYTES = bytes.fromhex(BIN_LOG_SYNC_START_STR)
-
class UnknownSerialDevice(Exception):
"""Exception raised when no device is specified."""
@@ -141,82 +207,32 @@
class HandleBinaryData(Transform):
"""Miniterm transform to handle incoming byte data."""
- def __init__(self) -> None:
- self.data = bytes()
- self.timestamp_prefix = ' delta_microseconds:'
- self.vbus_prefix = ' vbus:'
- self.vshunt_prefix = ' vshunt:'
- self.start_time = time.time()
- self.time_format = '%Y%m%d %H:%M:%S.%f'
- self.binary_format_started = False
+ def __init__(self, gonk_log_stream: GonkLogStream) -> None:
+ self.gonk_log_stream = gonk_log_stream
- def _parse_proto(self, proto_bytes: bytes) -> str:
- # Parse the proto message.
- try:
- framed_proto = FramedProto()
- framed_proto.ParseFromString(proto_bytes)
- vbus_values = []
- vshunt_values = []
- for adc_measure in framed_proto.payload.adc_measurements:
- vbus_values.append(adc_measure.vbus_value)
- vshunt_values.append(adc_measure.vshunt_value)
-
- # TODO(tonymd): Use Python logging and separate output file
- output = [
- # Host time
- datetime.now().strftime(self.time_format),
- # Update byte size
- f' size: {str(len(proto_bytes))} ',
- self.timestamp_prefix,
- # Delta microseconds
- str(framed_proto.payload.timestamp),
- # Vshunt values
- self.vshunt_prefix,
- ','.join(str(value) for value in vshunt_values),
- # Vbus values
- self.vbus_prefix,
- ','.join(str(value) for value in vbus_values),
- ]
- return ' '.join(output) + '\n'
- except DecodeError:
- # TODO(tonymd): Handle failed packets.
- return 'FramedProto.DecodeError\n'
-
- def rx(self, text, data=None):
+ def rx(self, text: str, data: Optional[bytes] = None) -> str:
"""Text received from the serial port."""
- if not data:
- return text
-
- # Concat data with any existing captures
- self.data = self.data + data
-
- # Check for binary start bytes.
- if BIN_LOG_SYNC_START_BYTES in self.data:
- self.binary_format_started = True
- if not self.binary_format_started:
- return text
-
- # Check for a complete proto capture.
- sections = self.data.split(BIN_LOG_SYNC_START_BYTES, maxsplit=2)
- if len(sections) < 3:
- # Don't print anything / filter out this text
+ if data:
+ self.gonk_log_stream.write(data)
return ''
-
- # Section 0 contains previous bytes not between two proto start bytes.
- _discard_bytes = sections[0]
- # Section 1 is a complete proto packet.
- proto_bytes = BIN_LOG_SYNC_START_BYTES + sections[1]
-
- # Done, reset self.data to the remaining bytes minus the above packet.
- self.data = BIN_LOG_SYNC_START_BYTES + sections[2]
-
- return self._parse_proto(proto_bytes)
-
- def tx(self, text):
- """Text to be sent to the serial port."""
return text
- def echo(self, text):
+
+class DebugSerialIO(Transform):
+ """Print sent and received data to stderr."""
+ def rx(self, text: str) -> str:
+ """Text received from the serial port."""
+ sys.stderr.write('[Recv: {!r}] '.format(text))
+ sys.stderr.flush()
+ return text
+
+ def tx(self, text: str):
+ """Text to be sent to the serial port."""
+ sys.stderr.write(' [Send: {!r}] '.format(text))
+ sys.stderr.flush()
+ return text
+
+ def echo(self, text: str):
"""Text to be sent but displayed on console."""
return text
@@ -277,24 +293,105 @@
"""Write a series of bytes to serial."""
# Write out the bitstream in batches.
- print('Sending bitstream...')
+ _LOG.info('Sending bitstream...')
written_bytes: int = 0
for byte_batch in batched(bitstream_bytes, 8):
result = serial_instance.write(byte_batch)
if result:
written_bytes += result
serial_instance.flush()
- print(f'Done sending bitstream. Wrote {written_bytes}')
+ _LOG.info('Done sending bitstream. Wrote %d', written_bytes)
def main(
+ # pylint: disable=too-many-arguments
baudrate: int,
+ databases: Iterable,
bitstream_file: Optional[Path],
port: Optional[str] = None,
product: Optional[str] = None,
serial_number: Optional[str] = None,
+ logfile: Optional[str] = None,
+ host_logfile: Optional[str] = None,
+ device_logfile: Optional[str] = None,
+ json_logfile: Optional[str] = None,
+ log_colors: Optional[bool] = False,
+ merge_device_and_host_logs: bool = False,
+ verbose: bool = False,
+ log_to_stderr: bool = False,
) -> int:
"""Write a bitstream file over serial while monitoring output."""
+
+ if not logfile:
+ # Create a temp logfile to prevent logs from appearing over stdout. This
+ # would corrupt the prompt toolkit UI.
+ logfile = python_logging.create_temp_log_file()
+
+ if log_colors is None:
+ log_colors = True
+ colors = pw_cli.color.colors(log_colors)
+ log_level = logging.DEBUG if verbose else logging.INFO
+ logger_name_format = colors.cyan('%(name)s')
+ logger_message_format = f'[{logger_name_format}] %(levelname)s %(message)s'
+
+ pw_cli_log.install(
+ level=log_level,
+ use_color=log_colors,
+ hide_timestamp=False,
+ log_file=logfile,
+ message_format=logger_message_format,
+ )
+
+ if device_logfile:
+ pw_cli_log.install(
+ level=log_level,
+ use_color=log_colors,
+ hide_timestamp=False,
+ log_file=device_logfile,
+ logger=_DEVICE_LOG,
+ message_format=logger_message_format,
+ )
+ if host_logfile:
+ pw_cli_log.install(
+ level=log_level,
+ use_color=log_colors,
+ hide_timestamp=False,
+ log_file=host_logfile,
+ logger=_ROOT_LOG,
+ message_format=logger_message_format,
+ )
+
+ # By default don't send device logs to the root logger.
+ _DEVICE_LOG.propagate = False
+ if merge_device_and_host_logs:
+ # Add device logs to the default logfile.
+ pw_cli_log.install(
+ level=log_level,
+ use_color=log_colors,
+ hide_timestamp=False,
+ log_file=logfile,
+ logger=_DEVICE_LOG,
+ message_format=logger_message_format,
+ )
+
+ if json_logfile:
+ json_filehandler = logging.FileHandler(json_logfile, encoding='utf-8')
+ json_filehandler.setLevel(log_level)
+ json_filehandler.setFormatter(python_logging.JsonLogFormatter())
+ _DEVICE_LOG.addHandler(json_filehandler)
+
+ if log_to_stderr:
+ pw_cli_log.install(
+ level=log_level,
+ use_color=log_colors,
+ hide_timestamp=False,
+ message_format=logger_message_format,
+ )
+
+ _LOG.setLevel(log_level)
+ _DEVICE_LOG.setLevel(log_level)
+ _ROOT_LOG.setLevel(log_level)
+
# Init serial port.
if port is None:
port = get_serial_port(product=product, serial_number=serial_number)
@@ -305,19 +402,25 @@
serial_instance = Serial(port=port, baudrate=baudrate, timeout=0.1)
+ detokenizer = detokenize.Detokenizer(tokens.Database.merged(*databases),
+ show_errors=True)
+
# Use pyserial miniterm to monitor recieved data.
miniterm = MinitermBinary(
serial_instance,
- echo=False,
- eol='crlf',
+ echo=True,
+ eol='lf',
filters=(),
)
+
# Use Ctrl-C as the exit character. (Miniterm default is Ctrl-])
miniterm.exit_character = chr(0x03)
miniterm.set_rx_encoding('utf-8', errors='backslashreplace')
miniterm.set_tx_encoding('utf-8')
- miniterm.rx_transformations.append(HandleBinaryData())
+ gonk_log_stream = GonkLogStream(detokenizer)
+ miniterm.rx_transformations.append(HandleBinaryData(gonk_log_stream))
+ miniterm.tx_transformations.append(DebugSerialIO())
# Start monitoring serial data.
miniterm.start()
