From 1f1e53d1dfc6138a5e0b77278b713a49893779d3 Mon Sep 17 00:00:00 2001 From: liquidraver <504870+liquidraver@users.noreply.github.com> Date: Sun, 27 Sep 2026 09:19:49 +0200 Subject: [PATCH] Make Packetlogging Great Again --- docs/DESIGN.md | 6 + .../RELEASE_NOTES_1.17.6a-zephcore.md | 23 +++- zephcore/Kconfig | 18 +-- zephcore/app/RepeaterMesh.cpp | 3 +- zephcore/app/RoomServerMesh.cpp | 3 +- zephcore/app/main_observer.cpp | 29 +++++ zephcore/boards/common/healthcheck.conf | 8 +- zephcore/boards/common/nrf54l_common.conf | 5 - zephcore/boards/common/packet_logging.conf | 28 +---- .../boards/nrf52840/xiao_nrf52840/board.conf | 6 - zephcore/helpers/PacketLog.h | 9 ++ .../0019-usb-cdc-acm-poll-out-flush.patch | 49 ++++++++ zephcore/src/main_companion.cpp | 8 ++ zephcore/src/server_main_common.cpp | 111 +++++++++++++----- 14 files changed, 225 insertions(+), 81 deletions(-) create mode 100644 zephcore/patches/zephyr/0019-usb-cdc-acm-poll-out-flush.patch diff --git a/docs/DESIGN.md b/docs/DESIGN.md index 0680eac..c89d383 100644 --- a/docs/DESIGN.md +++ b/docs/DESIGN.md @@ -242,6 +242,9 @@ sequenceDiagram which only enqueue and signal. - R6.3 No busy-wait or unbounded blocking on the main thread. - R6.4 The radio is RX 24/7; it is never PM-suspended. +- R6.5 The text console of the servers and the observer has one writer, the main thread: CLI echo, replies and + packet-log lines. A second writer in a context that preempts it (the echo once ran on sysworkq) or that it + preempts (the log thread) splits lines, and line-parsing consumers such as observer feeds lose packets. ### 6.2 Execution contexts @@ -315,6 +318,9 @@ it polls external state. Repeater and room server share one loop (`server_main_c ### 8.6 Observability - Zephyr logging per module; `debug.conf`; RTT on nRF, console on ESP32. +- Packet logging (`packet_logging.conf`): upstream's `MESH_PACKET_LOGGING` RAW/RX/TX lines through `printk`, with + the logging subsystem off so they share the console only with the CLI (R6.5). Every packet is one whole line + starting at column 0, also while a host is typing commands (bench-verified SF7 BW62.5 to BW500). - CLI `get`/`stats-*`, `get pwrmgt.bootreason` (reset cause, shutdown reason, and the last fatal error with its pc). - Host regression suite (`tests/`, CI with ASan/UBSan) over the production sources. diff --git a/releasenotes/RELEASE_NOTES_1.17.6a-zephcore.md b/releasenotes/RELEASE_NOTES_1.17.6a-zephcore.md index 5997456..be2242c 100644 --- a/releasenotes/RELEASE_NOTES_1.17.6a-zephcore.md +++ b/releasenotes/RELEASE_NOTES_1.17.6a-zephcore.md @@ -152,6 +152,25 @@ partial ZephCore-specific decode. - Sprites are now drawn with a one-pixel black halo so they stay visible against similarly-lit backgrounds. +## Packet logging you can feed to an observer + +Repeater and room-server builds with `packet_logging.conf` (the Arduino-format `RAW:` / `RX,` / `TX,` lines +that tools such as mctomqtt read from the USB port) now give exactly one whole line per packet: + +- **Only packet lines and CLI replies on the port.** The Zephyr logging subsystem is off in these builds, so + `` lines (GPS fixes and the like) no longer appear, and can no longer land in the middle of a packet line. +- **Sending commands no longer breaks packet lines.** The CLI echoed typed characters from a background thread + that could interrupt a packet line mid-way; a tool asking `get public.key` while traffic flowed could corrupt the + line being printed. The echo now runs on the same thread as the packet log. +- **Every packet line starts at the beginning of a line**, even while someone is halfway through typing a + command: the partial command is moved aside and reprinted on the next keystroke. +- A long paste into the CLI is no longer cut when the device is busy; input now waits instead of being dropped. + +Bench-tested with a T1000-E receiving bursts from a second node on SF7 at 62.5, 125, 250 and 500 kHz, short and +maximum-length packets, with and without a host typing into the port: every packet received was logged whole. +The same builds also caught a regression in the Zephyr version this release moves to, which would have cut any +USB console output longer than 64 bytes (packet lines, CLI replies); it is patched, and never shipped. + --- ## Also in this release @@ -179,4 +198,6 @@ partial ZephCore-specific decode. - **Board manifests**: every board now has a single `zephcore.yml` describing its release role, variants and capabilities, replacing board-name regex lists scattered across the build scripts. - **System design docs published**: `docs/DESIGN.md` and nine architecture decision records covering - the choices made in this restructure. \ No newline at end of file + the choices made in this restructure. +- **`healthcheck.conf` now logs.** It never turned the logging subsystem on, so a repeater built with it + printed nothing. A few configuration lines that had no effect on any build were removed. \ No newline at end of file diff --git a/zephcore/Kconfig b/zephcore/Kconfig index 82fbb6d..e5ec881 100644 --- a/zephcore/Kconfig +++ b/zephcore/Kconfig @@ -93,10 +93,6 @@ module = ZEPHCORE_UI_ACTIONS module-str = zephcore_ui_actions source "$(ZEPHYR_BASE)/subsys/logging/Kconfig.template.log_config" -module = ZEPHCORE_WIFI_OTA -module-str = zephcore_wifi_ota -source "$(ZEPHYR_BASE)/subsys/logging/Kconfig.template.log_config" - module = ZEPHCORE_OBSERVER module-str = zephcore_observer source "$(ZEPHYR_BASE)/subsys/logging/Kconfig.template.log_config" @@ -737,20 +733,14 @@ menu "Debug & Logging" config ZEPHCORE_PACKET_LOGGING bool "Enable mesh packet logging" default n - depends on LOG + depends on PRINTK help Log all RX and TX mesh packets in Arduino-compatible format. Output format matches Arduino MESH_PACKET_LOGGING exactly: "HH:MM:SS - D/M/YYYY U: RX, len=N (type=N, route=D/F, payload_len=N) SNR=N RSSI=N score=N time=N hash=XXXX [XX -> XX]" - -config ZEPHCORE_PACKET_LOGGING_ONLY - bool "Quiet mode - only packet logs, no debug spam" - default n - depends on ZEPHCORE_PACKET_LOGGING - help - When enabled, suppresses all other log messages and only outputs - packet logging (RAW, RX, TX lines). Uses printk() to bypass - log level filtering. + The lines are printk(), so they need no logging subsystem: + packet_logging.conf keeps CONFIG_LOG=n and the console carries + nothing else. endmenu diff --git a/zephcore/app/RepeaterMesh.cpp b/zephcore/app/RepeaterMesh.cpp index 4f22a8d..8d3b2c8 100644 --- a/zephcore/app/RepeaterMesh.cpp +++ b/zephcore/app/RepeaterMesh.cpp @@ -653,6 +653,7 @@ void RepeaterMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int len) /* Arduino-compatible RAW packet hex dump */ static char hex_buf[MAX_TRANS_UNIT * 2 + 1]; mesh::Utils::toHex(hex_buf, raw, len); + zc_console_line_start(); printk("%s RAW: %s\n", getLogDateTime(), hex_buf); #endif (void)snr; @@ -1355,7 +1356,7 @@ void RepeaterMesh::handleCommand(uint32_t sender_timestamp, char* command, char* } /* Blank line: nothing to run. The USB reader forwards these (see - * cli_rx_work_fn) because `region load` commits on one -- which is + * cli_rx_bytes) because `region load` commits on one -- which is * handled above, before this returns. */ if (StrHelper::isBlank(command)) { reply[0] = 0; return; } diff --git a/zephcore/app/RoomServerMesh.cpp b/zephcore/app/RoomServerMesh.cpp index 9c9443b..30298bf 100644 --- a/zephcore/app/RoomServerMesh.cpp +++ b/zephcore/app/RoomServerMesh.cpp @@ -280,6 +280,7 @@ void RoomServerMesh::logRxRaw(float snr, float rssi, const uint8_t raw[], int le /* Arduino-compatible RAW packet hex dump */ static char hex_buf[MAX_TRANS_UNIT * 2 + 1]; mesh::Utils::toHex(hex_buf, raw, len); + zc_console_line_start(); printk("%s RAW: %s\n", getLogDateTime(), hex_buf); #endif (void)snr; @@ -930,7 +931,7 @@ void RoomServerMesh::handleCommand(uint32_t sender_timestamp, char* command, cha } /* Blank line: nothing to run. The USB reader forwards these (see - * cli_rx_work_fn) because `region load` commits on one -- which is + * cli_rx_bytes) because `region load` commits on one -- which is * handled above, before this returns. */ if (StrHelper::isBlank(command)) { reply[0] = 0; return; } diff --git a/zephcore/app/main_observer.cpp b/zephcore/app/main_observer.cpp index 80cbff8..23ac57a 100644 --- a/zephcore/app/main_observer.cpp +++ b/zephcore/app/main_observer.cpp @@ -212,6 +212,32 @@ static void print_banner(void) /* ========== CLI RX processing ========== */ +#if IS_ENABLED(CONFIG_ZEPHCORE_PACKET_LOGGING) +/* A packet line ended the echo of a half-typed command (helpers/PacketLog.h). */ +static bool cli_echo_cut; + +extern "C" void zc_console_line_start(void) +{ + if (cli_line_idx > 0 && !cli_echo_cut) { + cli_print("\r\n"); + cli_echo_cut = true; + } +} + +/* Before echoing more of a cut command, reprint what was typed so far. */ +static void cli_echo_resume(void) +{ + if (cli_echo_cut && usb_dev) { + for (uint16_t i = 0; i < cli_line_idx; i++) { + uart_poll_out(usb_dev, cli_line[i]); + } + } + cli_echo_cut = false; +} +#else +static inline void cli_echo_resume(void) {} +#endif + static void process_cli_rx(void) { uint8_t byte; @@ -237,15 +263,18 @@ static void process_cli_rx(void) } cli_line_idx = 0; } + cli_echo_resume(); /* nothing left to reprint: just clears */ cli_print("\r\n"); } else if (byte == 0x7F || byte == 0x08) { if (cli_line_idx > 0) { + cli_echo_resume(); cli_line_idx--; uart_poll_out(usb_dev, '\b'); uart_poll_out(usb_dev, ' '); uart_poll_out(usb_dev, '\b'); } } else if (cli_line_idx < sizeof(cli_line) - 1) { + cli_echo_resume(); uart_poll_out(usb_dev, byte); cli_line[cli_line_idx++] = (char)byte; } diff --git a/zephcore/boards/common/healthcheck.conf b/zephcore/boards/common/healthcheck.conf index 2ffff91..38bcc71 100644 --- a/zephcore/boards/common/healthcheck.conf +++ b/zephcore/boards/common/healthcheck.conf @@ -5,6 +5,10 @@ # Cranks all ZephCore log modules to INF (some to DBG where safe), # enables packet logging, and sizes buffers for the extra output. +# prj.conf is production (CONFIG_LOG=n): without this, every level below and +# both backends are silently dropped and the build logs nothing. +CONFIG_LOG=y + # ========== ZephCore module log levels ========== # Main mesh logic (Mesh, BaseChatMesh, RepeaterMesh, Utils) CONFIG_ZEPHCORE_MAIN_LOG_LEVEL_DBG=y @@ -39,9 +43,9 @@ CONFIG_LOG_BUFFER_SIZE=16384 CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD=1 CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=4096 -# Backends — UART (USB CDC) so you can read on a terminal +# Backend — UART (USB CDC) so you can read on a terminal. For RTT add +# -DCONFIG_USE_SEGGER_RTT=y -DCONFIG_LOG_BACKEND_RTT=y (as in debug.conf). CONFIG_LOG_BACKEND_UART=y -CONFIG_LOG_BACKEND_RTT=y # Increase system workqueue stack to handle DBG-level log calls from ISR context CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096 diff --git a/zephcore/boards/common/nrf54l_common.conf b/zephcore/boards/common/nrf54l_common.conf index 0542227..da5946f 100644 --- a/zephcore/boards/common/nrf54l_common.conf +++ b/zephcore/boards/common/nrf54l_common.conf @@ -8,11 +8,6 @@ # XIAO nRF54L15 has a SAMD11 bridge chip (CMSIS-DAP) that converts UART20 → USB CDC # on the host side. Flashing is via SWD through CMSIS-DAP (west flash / openocd). -# ========== CPU Clock: DVFS low (64 MHz) for power saving ========== -# nRF54L15 supports 64/128/320 MHz via HSFLL DVFS. -# 64 MHz is plenty for event-driven companion firmware. -CONFIG_CLOCK_CONTROL_NRF_HSFLL_LOCAL_REQ_LOW_FREQ=y - # ========== BLE: nRF54L-specific controller settings ========== # TX power: +8 dBm (max — same open-source BLE controller as nRF52) CONFIG_BT_CTLR_TX_PWR_PLUS_8=y diff --git a/zephcore/boards/common/packet_logging.conf b/zephcore/boards/common/packet_logging.conf index 3f9be60..9971a32 100644 --- a/zephcore/boards/common/packet_logging.conf +++ b/zephcore/boards/common/packet_logging.conf @@ -2,32 +2,16 @@ # Build: west build -b zephcore --pristine -- \ # -DEXTRA_CONF_FILE="boards/common/repeater.conf;boards/common/packet_logging.conf" # -# Output: Clean packet logs only (RAW, RX, TX lines) -# No debug spam from zephcore_lora, zephcore_dispatcher, etc. +# Output: packet lines (RAW, RX, TX) and CLI replies, nothing else. For +# consumers that parse the console line by line (mctomqtt, observers). # # Example output: # 14:01:24 - 10/2/2026 U RAW: 150341E248D93B1BA948BC7E... # 14:01:24 - 10/2/2026 U: RX, len=40 (type=5, route=F, payload_len=35) SNR=1 RSSI=-106 score=949 time=476 hash=C3CD323A5235CB60 -# Enable logging subsystem (needed for LOG_* macros) -CONFIG_LOG=y -CONFIG_LOG_MODE_DEFERRED=y +# Packet lines are printk(). The logging subsystem stays off, as in production: +# with it on, the log thread (lowest priority) is a second console writer, and +# the mesh thread preempting it mid-message splits packet lines. +CONFIG_LOG=n -# Send printk directly to console (USB CDC), not through log system -# This avoids needing CONFIG_LOG_BACKEND_UART -CONFIG_LOG_PRINTK=n - -# Enable packet logging CONFIG_ZEPHCORE_PACKET_LOGGING=y -CONFIG_ZEPHCORE_PACKET_LOGGING_ONLY=y - -# Silence all module logs (packet logs use printk, bypass log levels) -CONFIG_ZEPHCORE_LORA_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_BLE_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_BOARD_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_DATASTORE_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_SENSORS_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_GPS_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_USB_LOG_LEVEL_OFF=y -CONFIG_ZEPHCORE_UI_ACTIONS_LOG_LEVEL_OFF=y -CONFIG_LORA_LOG_LEVEL_OFF=y diff --git a/zephcore/boards/nrf52840/xiao_nrf52840/board.conf b/zephcore/boards/nrf52840/xiao_nrf52840/board.conf index fd30e14..ffe26c5 100644 --- a/zephcore/boards/nrf52840/xiao_nrf52840/board.conf +++ b/zephcore/boards/nrf52840/xiao_nrf52840/board.conf @@ -6,9 +6,3 @@ CONFIG_ZEPHCORE_BOARD_NAME="XIAO nRF52840" CONFIG_BT_DIS_MODEL_NUMBER_STR="Seeed XIAO nRF52840" CONFIG_ZEPHCORE_SD_FWID=0x0123 - -# Default debug (debug.conf) sends LOG_* to RTT only. Plain XIAO is usually -# flashed/debugged over USB without an SWD J-Link — enable UART backend so -# LOG_* appears on the CDC ACM serial port (same as zephyr,console). -# RTT remains enabled for J-Link; use DROP mode (see zephcore_common.conf). -CONFIG_LOG_BACKEND_UART=y diff --git a/zephcore/helpers/PacketLog.h b/zephcore/helpers/PacketLog.h index 1daa918..47b4abf 100644 --- a/zephcore/helpers/PacketLog.h +++ b/zephcore/helpers/PacketLog.h @@ -16,6 +16,13 @@ #if IS_ENABLED(CONFIG_ZEPHCORE_PACKET_LOGGING) +/* Called before every packet line; defined by the role's main + * (server_main_common.cpp, main_observer.cpp, main_companion.cpp). If the + * user is part-way through typing a CLI command, its echo is ended with a + * newline first, so a packet line always starts at column 0 for consumers + * that parse the console line by line. */ +extern "C" void zc_console_line_start(void); + static inline bool packet_log_has_addrs(uint8_t ptype) { return ptype == PAYLOAD_TYPE_PATH || ptype == PAYLOAD_TYPE_REQ || @@ -29,6 +36,7 @@ static inline void packet_log_rx(const char *datetime, const mesh::Packet *pkt, static char hash_hex[MAX_HASH_SIZE * 2 + 1]; uint8_t ptype = pkt->getPayloadType(); + zc_console_line_start(); pkt->calculatePacketHash(packet_hash); mesh::Utils::toHex(hash_hex, packet_hash, MAX_HASH_SIZE); if (packet_log_has_addrs(ptype)) { @@ -52,6 +60,7 @@ static inline void packet_log_tx(const char *datetime, const mesh::Packet *pkt) { uint8_t ptype = pkt->getPayloadType(); + zc_console_line_start(); if (packet_log_has_addrs(ptype)) { printk("%s: TX, len=%d (type=%d, route=%s, payload_len=%d) [%02X -> %02X]\n", datetime, pkt->getRawLength(), ptype, diff --git a/zephcore/patches/zephyr/0019-usb-cdc-acm-poll-out-flush.patch b/zephcore/patches/zephyr/0019-usb-cdc-acm-poll-out-flush.patch new file mode 100644 index 0000000..45c5940 --- /dev/null +++ b/zephcore/patches/zephyr/0019-usb-cdc-acm-poll-out-flush.patch @@ -0,0 +1,49 @@ +USB CDC ACM: cdc_acm_poll_out() flushes a full TX buffer instead of dropping. + +6d69698de74 ("cdc_acm: tx throughput improvements", merged 2026-09-25) +replaced the TX ring buffer with net_bufs. poll_out() now only fills the one +`current` 64 B buffer, and moving on to the next is left to tx_fifo_work. A +printk burst from a thread that does not yield (a packet log line is 100-300 B) +fills that buffer and every further byte is discarded ("No TX buffer available, +discard data") because the work item cannot run meanwhile: RAW hex cut after +~64 B, RX lines losing their start, CLI replies such as `get public.key` +corrupted. The old ring buffer accepted ~1 KB per burst. + +Enqueue the full buffer from poll_out() (thread context only) and retry once. +It never blocks, so an unplugged host cannot hang the caller; bytes are +dropped only when the buffer pool is exhausted, as before the rewrite. + +Found 2026-09-26 with a rak3401_1watt repeater + packet_logging.conf feeding +mctomqtt. Not fixed on Zephyr main as of 3e7672a71bd; no upstream issue found. + +diff --git a/subsys/usb/device_next/class/usbd_cdc_acm.c b/subsys/usb/device_next/class/usbd_cdc_acm.c +index 3957daa167b..5492f6c5ce4 100644 +--- a/subsys/usb/device_next/class/usbd_cdc_acm.c ++++ b/subsys/usb/device_next/class/usbd_cdc_acm.c +@@ -1143,6 +1143,7 @@ static void cdc_acm_poll_out(const struct device *dev, const unsigned char c) + struct cdc_acm_uart_data *const data = dev->data; + k_spinlock_key_t key; + uint32_t wrote; ++ bool flushed = false; + + while (true) { + key = k_spin_lock(&data->lock); +@@ -1153,6 +1154,18 @@ static void cdc_acm_poll_out(const struct device *dev, const unsigned char c) + break; + } + ++ /* ZephCore: the current buffer is full. Hand it to the USB stack ++ * now and continue in a fresh one from the pool, rather than ++ * discarding until tx_fifo_work runs (it cannot run while this ++ * thread is inside a long printk burst). Drops only once the pool ++ * itself is exhausted, as the old ring buffer did. ++ */ ++ if (!flushed && !k_is_in_isr()) { ++ flushed = true; ++ cdc_acm_tx_fifo_enqueue(dev); ++ continue; ++ } ++ + if (k_is_in_isr() || !data->flow_ctrl) { + LOG_WRN_ONCE("No TX buffer available, discard data"); + goto cdc_acm_poll_out_schedule; diff --git a/zephcore/src/main_companion.cpp b/zephcore/src/main_companion.cpp index 0f72443..f6a8bc9 100644 --- a/zephcore/src/main_companion.cpp +++ b/zephcore/src/main_companion.cpp @@ -72,6 +72,14 @@ LOG_MODULE_REGISTER(zephcore_main, CONFIG_ZEPHCORE_MAIN_LOG_LEVEL); #include #endif +#if IS_ENABLED(CONFIG_ZEPHCORE_PACKET_LOGGING) +/* helpers/PacketLog.h hook, a no-op here: packet_logging.conf is for the + * repeater, room server and observer consoles. A companion's USB port carries + * the binary app protocol, and its text CLI echoes through its own TX ring + * (adapters/usb/ZephyrCompanionUSB.cpp). */ +extern "C" void zc_console_line_start(void) {} +#endif + /* Without this a BLE controller assert freezes the CPU at top IRQ priority * with no output; log the location and reboot. */ #if IS_ENABLED(CONFIG_BT_CTLR_ASSERT_HANDLER) diff --git a/zephcore/src/server_main_common.cpp b/zephcore/src/server_main_common.cpp index 0d25fdb..c8de5bd 100644 --- a/zephcore/src/server_main_common.cpp +++ b/zephcore/src/server_main_common.cpp @@ -127,25 +127,29 @@ static struct ring_buf usb_ring_buf; static char cli_line_buf[CLI_LINE_BUF_SIZE]; static char cli_reply_buf[256]; static uint16_t cli_line_idx; -/* Last byte seen by cli_rx_work_fn, for collapsing CRLF/LFCR pairs. Persists - * across work-item invocations, so a pair split across two USB packets still +/* Last byte seen by cli_rx_bytes, for collapsing CRLF/LFCR pairs. Persists + * across calls, so a pair split across two USB packets still * compares correctly. */ static uint8_t cli_prev_byte; -/* Completed CLI lines are handed to the MAIN thread for execution. Byte - * assembly + echo (cli_rx_work_fn) runs on sysworkq and touches no mesh - * state, but handleCommand() mutates the lock-free packet pool / dispatcher - * that loop() also touches — running it on sysworkq races the main loop. - * So we queue the finished line and let the event loop run handleCommand(). */ +/* The whole CLI runs on the MAIN thread: byte assembly and echo + * (cli_rx_bytes) as well as handleCommand(), which mutates the lock-free + * packet pool / dispatcher that loop() also touches. Keeping the echo there + * too makes main the console's only writer, so an echoed keystroke can never + * land inside a packet-log line (it did when the echo ran on sysworkq, which + * preempts main). A finished line still passes through the queue. */ struct cli_cmd_line { char buf[CLI_LINE_BUF_SIZE]; }; K_MSGQ_DEFINE(cli_cmd_queue, sizeof(struct cli_cmd_line), 4, 4); +/* Set by the ISR when usb_ring_buf is full and it stopped reading the port; + * main re-enables RX once it has drained the ring. Unread bytes wait in the + * USB driver (the host is NAKed), so a long paste is never cut. */ +static atomic_t cli_rx_paused; + /* Work items for event-driven processing */ -static void cli_rx_work_fn(struct k_work *work); static void maintenance_timer_fn(struct k_timer *timer); static void tx_drain_work_fn(struct k_work *work); static void initial_advert_work_fn(struct k_work *work); -K_WORK_DEFINE(cli_rx_work, cli_rx_work_fn); K_WORK_DELAYABLE_DEFINE(tx_drain_work, tx_drain_work_fn); K_WORK_DELAYABLE_DEFINE(initial_advert_work, initial_advert_work_fn); @@ -194,21 +198,58 @@ static void cli_uart_isr(const struct device *dev, void *user_data) if (uart_irq_rx_ready(dev)) { uint8_t buf[64]; - int recv_len = uart_fifo_read(dev, buf, sizeof(buf)); + uint32_t room = MIN(sizeof(buf), ring_buf_space_get(&usb_ring_buf)); + if (room == 0) { + /* Ring full: stop reading, main resumes (cli_rx_paused). */ + atomic_set(&cli_rx_paused, 1); + uart_irq_rx_disable(dev); + k_event_post(&mesh_events, MESH_EVENT_CLI_RX); + break; + } + int recv_len = uart_fifo_read(dev, buf, room); if (recv_len > 0) { ring_buf_put(&usb_ring_buf, buf, recv_len); - k_work_submit(&cli_rx_work); + k_event_post(&mesh_events, MESH_EVENT_CLI_RX); } } } } -/* CLI RX work - processes line-based CLI commands - * Matches Arduino behavior: echo each char, then " -> reply" on enter - */ -static void cli_rx_work_fn(struct k_work *work) +#if IS_ENABLED(CONFIG_ZEPHCORE_PACKET_LOGGING) +/* A packet line ended the echo of a half-typed command (helpers/PacketLog.h). + * Main thread only, like everything that writes the console. */ +static bool cli_echo_cut; + +extern "C" void zc_console_line_start(void) +{ + if (cli_line_idx > 0 && !cli_echo_cut) { + cli_print("\r\n"); + cli_echo_cut = true; + } +} + +/* Before echoing more of a cut command, reprint what was typed so far. */ +static void cli_echo_resume(void) +{ + if (cli_echo_cut && usb_dev) { + for (uint16_t i = 0; i < cli_line_idx; i++) { + uart_poll_out(usb_dev, cli_line_buf[i]); + } + } + cli_echo_cut = false; +} +#else +static inline void cli_echo_resume(void) {} +#endif + +/* CLI RX, on the main thread - assembles line-based CLI commands. + * Matches Arduino behavior: echo each char, then " -> reply" on enter. + * Returns true after queueing one finished line (the caller runs it before + * reading on, so a pasted block cannot overflow the 4-deep queue), false once + * the ring is empty. + */ +static bool cli_rx_bytes(void) { - ARG_UNUSED(work); uint8_t byte; while (ring_buf_get(&usb_ring_buf, &byte, 1) == 1) { @@ -237,21 +278,22 @@ static void cli_rx_work_fn(struct k_work *work) cli_line_buf, cli_line_idx > 40 ? "..." : ""); } - /* Hand the command to the main thread (see cli_cmd_queue). - * The reply + trailing newline are emitted there, exactly - * matching the previous inline output order. */ + /* Queue it for process_cli_commands(), which the caller + * runs before reading on; the reply + trailing newline are + * emitted there. */ struct cli_cmd_line c; strncpy(c.buf, cli_line_buf, sizeof(c.buf) - 1); c.buf[sizeof(c.buf) - 1] = '\0'; - if (k_msgq_put(&cli_cmd_queue, &c, K_NO_WAIT) == 0) { - k_event_post(&mesh_events, MESH_EVENT_CLI_RX); - } else { - cli_print("\r\n -> busy\r\n"); - } cli_line_idx = 0; + cli_echo_resume(); /* nothing left to reprint: just clears */ + if (k_msgq_put(&cli_cmd_queue, &c, K_NO_WAIT) == 0) { + return true; + } + cli_print("\r\n -> busy\r\n"); } else if (byte == 0x7F || byte == 0x08) { /* Backspace - echo backspace sequence */ if (cli_line_idx > 0) { + cli_echo_resume(); cli_line_idx--; if (usb_dev) { uart_poll_out(usb_dev, '\b'); @@ -261,12 +303,14 @@ static void cli_rx_work_fn(struct k_work *work) } } else if (cli_line_idx < sizeof(cli_line_buf) - 1) { /* Echo character back (like Arduino) */ + cli_echo_resume(); if (usb_dev) { uart_poll_out(usb_dev, byte); } cli_line_buf[cli_line_idx++] = (char)byte; } } + return false; } #ifdef ZEPHCORE_LORA @@ -498,14 +542,23 @@ static void server_event_loop(void) gps_process_event(); } -#ifdef ZEPHCORE_LORA - /* Run queued CLI commands here (main thread) BEFORE loop() drains - * any outbound packets they enqueued — keeps all mesh-state - * mutation on the main thread (see cli_cmd_queue). */ + /* Console input: assemble + echo, then run each finished line here + * (main thread) BEFORE loop() drains any outbound packets it + * enqueued — keeps all mesh-state mutation, and every console + * write, on the main thread (see cli_cmd_queue). */ if (events & MESH_EVENT_CLI_RX) { - process_cli_commands(); + while (cli_rx_bytes()) { +#ifdef ZEPHCORE_LORA + process_cli_commands(); +#endif + } + if (atomic_cas(&cli_rx_paused, 1, 0) && usb_dev) { + uart_irq_rx_enable(usb_dev); + } } +#ifdef ZEPHCORE_LORA + /* Deferred boot advert — sent on the main thread (see * initial_advert_work_fn); loop() below drains the queued packet. */ if (server_role && (events & MESH_EVENT_INIT_ADVERT)) {