Add debug log ring buffer with timestamps, log CLI subcommand

cmd/picomap/main.go

@@ -29,10 +29,12 @@ func main() {
 		err = cmdInfo()
 	case "load":
 		err = cmdLoad(args)
+	case "log":
+		err = cmdLog(args)
 	case "test":
 		err = cmdTest(args)
 	default:
-		slog.Error("unknown command", "cmd", cmd)
+		slog.Error("usage: picomap <info|load|log|test> [args...]")
 		os.Exit(1)
 	}
 	if err != nil {
@@ -128,6 +130,38 @@ func buildFirmware(buildDir string) error {
 	return nil
 }
 
+func cmdLog(_ []string) error {
+	devs, err := client.ListSerial()
+	if err != nil {
+		return err
+	}
+	if len(devs) == 0 {
+		return fmt.Errorf("no devices found")
+	}
+	for _, dev := range devs {
+		log := slog.With("dev", dev)
+		c, err := client.NewSerial(dev, 2*time.Second)
+		if err != nil {
+			log.Error("connect error", "err", err)
+			continue
+		}
+		resp, err := c.Log()
+		c.Close()
+		if err != nil {
+			log.Error("log error", "err", err)
+			continue
+		}
+		if len(resp.Entries) == 0 {
+			log.Info("no debug messages")
+			continue
+		}
+		for _, e := range resp.Entries {
+			log.Info("dlog", "t_us", e.TimestampUS, "msg", e.Message)
+		}
+	}
+	return nil
+}
+
 func cmdLoad(args []string) error {
 	target := "all"
 	if len(args) > 0 {

firmware/firmware.cpp

@@ -6,6 +6,7 @@ std::string_view firmware_name = "picomap";
 static constexpr handler_entry handlers[] = {
     {RequestPICOBOOT::ext_id, handle_picoboot},
     {RequestInfo::ext_id, handle_info},
+    {RequestLog::ext_id, handle_log},
 };
 
 int main() {

firmware/include/debug_log.h

@@ -0,0 +1,30 @@
+#pragma once
+#include <string>
+#include <string_view>
+#include <vector>
+#include "pico/time.h"
+#include "ring_buffer.h"
+
+struct log_entry {
+    uint32_t timestamp_us;
+    std::string message;
+};
+
+inline ring_buffer<log_entry, 32> g_debug_log;
+
+inline void dlog(std::string_view msg) {
+    g_debug_log.push(log_entry{static_cast<uint32_t>(time_us_32()), std::string(msg)});
+}
+
+inline std::vector<log_entry> dlog_drain() {
+    std::vector<log_entry> result;
+    uint16_t n = g_debug_log.used();
+    result.reserve(n);
+    for (uint16_t i = 0; i < n; i++) {
+        log_entry e;
+        g_debug_log.peek(std::span{&e, 1});
+        result.push_back(std::move(e));
+        g_debug_log.consume(1);
+    }
+    return result;
+}

firmware/include/handlers.h

@@ -9,3 +9,4 @@ extern std::string_view firmware_name;
 
 std::vector<std::vector<uint8_t>> handle_picoboot(uint32_t message_id, std::span<const uint8_t> payload);
 std::vector<std::vector<uint8_t>> handle_info(uint32_t message_id, std::span<const uint8_t> payload);
+std::vector<std::vector<uint8_t>> handle_log(uint32_t message_id, std::span<const uint8_t> payload);

firmware/include/ring_buffer.h

@@ -3,9 +3,9 @@
 #include <cstdint>
 #include <span>
 
-template <uint16_t N>
+template <typename T, uint16_t N>
 struct ring_buffer {
-    std::array<uint8_t, N> data = {};
+    std::array<T, N> data = {};
     uint16_t head = 0;
     uint16_t tail = 0;
 
@@ -13,13 +13,18 @@ struct ring_buffer {
     uint16_t free() const { return N - used(); }
     bool empty() const { return head == tail; }
 
-    void push(std::span<const uint8_t> src) {
+    void push(std::span<const T> src) {
         if (src.size() > free()) return;
-        for (auto b : src)
+        for (auto& v : src)
-            data[(tail++) % N] = b;
+            data[(tail++) % N] = v;
     }
 
-    uint16_t peek(std::span<uint8_t> dst) const {
+    void push(const T& v) {
+        if (free() == 0) return;
+        data[(tail++) % N] = v;
+    }
+
+    uint16_t peek(std::span<T> dst) const {
         uint16_t len = dst.size() < used() ? dst.size() : used();
         for (uint16_t i = 0; i < len; i++)
             dst[i] = data[(head + i) % N];
@@ -34,7 +39,7 @@ struct ring_buffer {
         }
     }
 
-    std::span<const uint8_t> read_contiguous() const {
+    std::span<const T> read_contiguous() const {
         uint16_t offset = head % N;
         uint16_t contig = N - offset;
         uint16_t pending = used();

firmware/include/usb_cdc.h

@@ -6,7 +6,7 @@
 #include "ring_buffer.h"
 
 struct usb_cdc {
-    ring_buffer<512> tx;
+    ring_buffer<uint8_t, 512> tx;
 
     void send(std::span<const uint8_t> data) {
         tx.push(data);

firmware/include/wire.h

@@ -53,6 +53,26 @@ struct ResponseInfo {
     auto as_tuple() { return std::tie(board_id, mac, ip, firmware_name); }
 };
 
+struct RequestLog {
+    static constexpr int8_t ext_id = 6;
+    auto as_tuple() const { return std::tie(); }
+    auto as_tuple() { return std::tie(); }
+};
+
+struct LogEntry {
+    uint32_t timestamp_us;
+    std::string message;
+    auto as_tuple() const { return std::tie(timestamp_us, message); }
+    auto as_tuple() { return std::tie(timestamp_us, message); }
+};
+
+struct ResponseLog {
+    static constexpr int8_t ext_id = 7;
+    std::vector<LogEntry> entries;
+    auto as_tuple() const { return std::tie(entries); }
+    auto as_tuple() { return std::tie(entries); }
+};
+
 struct RequestTest {
     static constexpr int8_t ext_id = 127;
     std::string name;

firmware/lib/dispatch.cpp

@@ -7,12 +7,14 @@
 #include "usb_cdc.h"
 #include "timer_queue.h"
 #include "net.h"
+#include "debug_log.h"
 
 static timer_queue timers;
 
 void dispatch_init() {
     tusb_init();
     net_init();
+    dlog("dispatch_init complete");
 }
 
 void dispatch_schedule_ms(uint32_t ms, std::function<void()> fn) {

firmware/lib/handlers.cpp

@@ -1,6 +1,7 @@
 #include "handlers.h"
 #include "pico/unique_id.h"
 #include "net.h"
+#include "debug_log.h"
 
 std::vector<std::vector<uint8_t>> handle_picoboot(uint32_t message_id, std::span<const uint8_t>) {
     return {encode_response(message_id, ResponsePICOBOOT{})};
@@ -17,3 +18,10 @@ std::vector<std::vector<uint8_t>> handle_info(uint32_t message_id, std::span<con
     resp.firmware_name = firmware_name;
     return {encode_response(message_id, resp)};
 }
+
+std::vector<std::vector<uint8_t>> handle_log(uint32_t message_id, std::span<const uint8_t>) {
+    ResponseLog resp;
+    for (auto& e : dlog_drain())
+        resp.entries.push_back(LogEntry{e.timestamp_us, std::move(e.message)});
+    return {encode_response(message_id, resp)};
+}

firmware/test.cpp

@@ -117,6 +117,7 @@ static std::vector<std::vector<uint8_t>> handle_test(uint32_t message_id, const
 static constexpr handler_entry handlers[] = {
     {RequestPICOBOOT::ext_id, handle_picoboot},
     {RequestInfo::ext_id, handle_info},
+    {RequestLog::ext_id, handle_log},
     {RequestTest::ext_id, typed_handler<RequestTest, handle_test>},
 };
 

lib/client/client.go

@@ -93,6 +93,10 @@ func (c *Client) Info() (*ResponseInfo, error) {
 	return roundTrip[ResponseInfo](c, &RequestInfo{})
 }
 
+func (c *Client) Log() (*ResponseLog, error) {
+	return roundTrip[ResponseLog](c, &RequestLog{})
+}
+
 func (c *Client) Test(name string) (*ResponseTest, error) {
 	return roundTrip[ResponseTest](c, &RequestTest{Name: name})
 }

lib/client/types.go

@@ -13,6 +13,17 @@ type ResponseInfo struct {
 	FirmwareName string
 }
 
+type RequestLog struct{}
+
+type LogEntry struct {
+	TimestampUS uint32
+	Message     string
+}
+
+type ResponseLog struct {
+	Entries []LogEntry
+}
+
 type RequestTest struct {
 	Name string
 }
@@ -44,6 +55,8 @@ func init() {
 	msgpack.RegisterExt(3, (*ResponsePICOBOOT)(nil))
 	msgpack.RegisterExt(4, (*RequestInfo)(nil))
 	msgpack.RegisterExt(5, (*ResponseInfo)(nil))
+	msgpack.RegisterExt(6, (*RequestLog)(nil))
+	msgpack.RegisterExt(7, (*ResponseLog)(nil))
 	msgpack.RegisterExt(127, (*RequestTest)(nil))
 	msgpack.RegisterExt(126, (*ResponseTest)(nil))
 }