diff --git a/device/prj.conf.overlays/nrf_shared.conf b/device/prj.conf.overlays/nrf_shared.conf index fcef162d5..b575874c8 100644 --- a/device/prj.conf.overlays/nrf_shared.conf +++ b/device/prj.conf.overlays/nrf_shared.conf @@ -64,7 +64,7 @@ CONFIG_SHELL_VT100_COMMANDS=y CONFIG_SHELL_VT100_COLORS=y CONFIG_SHELL_DEFAULT_TERMINAL_WIDTH=80 CONFIG_BT_SHELL=y -CONFIG_SHELL_BT_NUS=y +CONFIG_SHELL_BT_NUS=n CONFIG_HWINFO=y CONFIG_HWINFO_SHELL=y CONFIG_I2C=y @@ -72,7 +72,8 @@ CONFIG_I2C_SHELL=y CONFIG_STREAM_FLASH=y CONFIG_SETTINGS_SHELL=y CONFIG_SHELL_BACKENDS=y -CONFIG_SHELL_BACKEND_SERIAL=y +CONFIG_SHELL_BACKEND_SERIAL=n +CONFIG_UART_ASYNC_RX_HELPER=y CONFIG_BUILD_OUTPUT_HEX=y CONFIG_BUILD_OUTPUT_META=y diff --git a/device/prj.conf.overlays/uhk-80-right.conf b/device/prj.conf.overlays/uhk-80-right.conf index 15920b9ef..2257af1df 100644 --- a/device/prj.conf.overlays/uhk-80-right.conf +++ b/device/prj.conf.overlays/uhk-80-right.conf @@ -4,7 +4,5 @@ CONFIG_PINCTRL_DYNAMIC=y CONFIG_SHELL=y CONFIG_SHELL_AUTOSTART=y -CONFIG_SHELL_BACKEND_SERIAL=y -CONFIG_SHELL_BACKEND_SERIAL_API_ASYNC=y diff --git a/device/src/CMakeLists.txt b/device/src/CMakeLists.txt index 908727b59..54e4e8972 100644 --- a/device/src/CMakeLists.txt +++ b/device/src/CMakeLists.txt @@ -42,8 +42,11 @@ if(NOT CONFIG_BOARD_UHK_60_RIGHT) resend.c round_trip_test.c settings.c - shell.c - shell_backend_usb.c + shell/shell_backend_usb.c + shell/shell_transport_uhk.c + shell/shell_uhk.c + shell/shell_commands.c + shell/sinks.c state_sync.c thread_stats.c ) diff --git a/device/src/keyboard/oled/screens/debug_screen.c b/device/src/keyboard/oled/screens/debug_screen.c index c45959ba6..bed436f67 100644 --- a/device/src/keyboard/oled/screens/debug_screen.c +++ b/device/src/keyboard/oled/screens/debug_screen.c @@ -1,13 +1,15 @@ #include "debug_screen.h" +#include "keyboard/oled/widgets/widget_store.h" #include "keyboard/oled/widgets/widgets.h" widget_t splitter; widget_t* DebugScreen; void DebugScreen_Init() { - const uint8_t totalHeight = DISPLAY_HEIGHT - 2*DISPLAY_SHIFTING_MARGIN; //56 - const uint8_t debugLineHeight = 6; - const uint8_t consoleHeight = totalHeight - debugLineHeight; - splitter = SplitterWidget_BuildVertical(&ConsoleWidget, &DebugLineWidget, consoleHeight, true); - DebugScreen = &splitter; + // const uint8_t totalHeight = DISPLAY_HEIGHT - 2*DISPLAY_SHIFTING_MARGIN; //56 + // const uint8_t debugLineHeight = 6; + // const uint8_t consoleHeight = totalHeight - debugLineHeight; + // splitter = SplitterWidget_BuildVertical(&ConsoleWidget, &DebugLineWidget, consoleHeight, true); + // DebugScreen = &splitter; + DebugScreen = &ConsoleWidget; } diff --git a/device/src/keyboard/oled/widgets/console_widget.c b/device/src/keyboard/oled/widgets/console_widget.c index bce97f528..023d34239 100644 --- a/device/src/keyboard/oled/widgets/console_widget.c +++ b/device/src/keyboard/oled/widgets/console_widget.c @@ -19,6 +19,7 @@ static char consoleBuffer[CONSOLE_BUFFER_LINE_COUNT][CONSOLE_BUFFER_LINE_LENGTH] = {}; static uint8_t consoleBufferStart = 0; +static uint8_t currentCol = 0; static bool consoleBufferIsDirty = true; void ConsoleWidget_LayOut(widget_t* self, uint8_t x, uint8_t y, uint8_t w, uint8_t h) @@ -60,10 +61,37 @@ widget_t ConsoleWidget_Build() } +static void advanceLine(void) +{ + consoleBufferStart = (consoleBufferStart + 1) % CONSOLE_BUFFER_LINE_COUNT; + consoleBuffer[consoleBufferStart][0] = '\0'; + currentCol = 0; +} + +static const char shellPrompt[] = "uhk80:right$"; + static void logConstant(const char* text) { - consoleBufferStart = (consoleBufferStart+1) % CONSOLE_BUFFER_LINE_COUNT; - snprintf(&consoleBuffer[consoleBufferStart][0], CONSOLE_BUFFER_LINE_LENGTH, "%s", text); + for (const char* p = text; *p != '\0'; p++) { + if (currentCol == 0 && strncmp(p, shellPrompt, sizeof(shellPrompt) - 1) == 0) { + p += sizeof(shellPrompt) - 2; + consoleBuffer[consoleBufferStart][currentCol++] = '$'; + consoleBuffer[consoleBufferStart][currentCol] = '\0'; + continue; + } + if (*p == '\n') { + if (currentCol > 0) { + advanceLine(); + } + } else if (*p == '\r') { + // skip + } else { + if (currentCol < CONSOLE_BUFFER_LINE_LENGTH - 1) { + consoleBuffer[consoleBufferStart][currentCol++] = *p; + consoleBuffer[consoleBufferStart][currentCol] = '\0'; + } + } + } consoleBufferIsDirty = true; diff --git a/device/src/logger_priority.c b/device/src/logger_priority.c index 1f6fbb88f..188d3936e 100644 --- a/device/src/logger_priority.c +++ b/device/src/logger_priority.c @@ -52,7 +52,7 @@ int set_thread_priority_by_name(const char *thread_name, int new_priority) { void Logger_SetPriority(bool high) { int8_t priority = high ? -1 : 14; set_thread_priority_by_name("logging", K_PRIO_PREEMPT(priority)); - set_thread_priority_by_name("shell_uart", K_PRIO_PREEMPT(priority)); + set_thread_priority_by_name("UhkShell", K_PRIO_PREEMPT(priority)); set_thread_priority_by_name("shell_rtt", K_PRIO_PREEMPT(priority)); } diff --git a/device/src/main.c b/device/src/main.c index df1ea0ebb..cb0a8d945 100644 --- a/device/src/main.c +++ b/device/src/main.c @@ -21,6 +21,8 @@ #include "keyboard/i2c.h" #include "peripherals/merge_sensor.h" #include "shell.h" +#include "shell/shell_transport_uhk.h" +#include "shell/shell_uhk.h" #include "device.h" #include "usb/usb.h" #include "bt_conn.h" @@ -52,7 +54,6 @@ #include "test_suite/test_suite.h" #include "wormhole.h" #include "power_mode.h" -#include "proxy_log_backend.h" #include "logger_priority.h" #include "keyboard/uart_modules.h" @@ -208,13 +209,11 @@ void mainRuntime(void) { PinWiring_Resume(); - ReinitShell(); + ShellUartTransport_Reinit(); } - // Needs to be after ReinitShell, probably + // Needs to be after ShellUartTransport_Reinit, probably InitShellCommands(); - InitProxyLogBackend(); - Shell_WaitUntilInitialized(); Logger_SetPriority(true); diff --git a/device/src/pin_wiring.c b/device/src/pin_wiring.c index 48e96033e..2c8de065c 100644 --- a/device/src/pin_wiring.c +++ b/device/src/pin_wiring.c @@ -1,5 +1,5 @@ #include "attributes.h" -#include "shell.h" +#include "shell/shell_transport_uhk.h" #include "bt_conn.h" #include "device.h" #include "keyboard/charger.h" @@ -21,7 +21,6 @@ #include "mouse_keys.h" #include "config_manager.h" #include -#include #include #include "connections.h" #include "logger_priority.h" @@ -236,7 +235,7 @@ void PinWiring_SelectRouting(void) { } void PinWiring_UninitShell(void) { - UninitShell(); + ShellUartTransport_Uninit(); uninitUart(&uart0); } diff --git a/device/src/proxy_log_backend.c b/device/src/proxy_log_backend.c index 69200846e..f5abffc11 100644 --- a/device/src/proxy_log_backend.c +++ b/device/src/proxy_log_backend.c @@ -1,148 +1,110 @@ -#include "proxy_log_backend.h" #include #include -#include -#include #include -#include #include -#include #include #include #include -#include "attributes.h" #include "logger.h" #include "macros/status_buffer.h" -#include "trace.h" -#include "wormhole.h" -#include "zephyr/logging/log_core.h" +#include "shell/sinks.h" #include "config_manager.h" #include "usb_log_buffer.h" -#include "config_manager.h" - -typedef struct { - bool outputToStatusBuffer; - bool outputToUsbBuffer; - bool outputToOled; -} proxy_log_context_t; - -#define PROXY_BACKEND_BUFFER_SIZE 2048 -bool ProxyLog_IsInPanicMode = false; - -static void processLog(const struct log_backend *const backend, union log_msg_generic *msg); - -void panic(const struct log_backend *const backend) { - StateWormhole_Open(); - StateWormhole.persistStatusBuffer = true; - - if (!ProxyLog_IsInPanicMode) { - ProxyLog_IsInPanicMode = true; - - MacroStatusBuffer_Validate(); - printk("===== PANIC =====\n"); - Trace_Print(LogTarget_ErrorBuffer, "crash/panic"); - } - -}; +// --- Log output callback --- static int outputFunc(uint8_t *data, size_t length, void *ctx) { - proxy_log_context_t* outputs = (proxy_log_context_t*)ctx; + shell_sinks_t *sinks = (shell_sinks_t *)ctx; - if (outputs->outputToStatusBuffer) { + if (sinks->toStatusBuffer) { Macros_SanitizedPut(data, data + length); } - if (outputs->outputToUsbBuffer) { + if (sinks->toUsbBuffer) { UsbLogBuffer_Print(data, length); } - if (outputs->outputToOled) { - LogO("%.*s", length, data); + if (sinks->toOled) { + LogO("%.*s", (int)length, data); } return length; } -// Allocate memory for actual log processing +// --- Log output buffer --- + #define LOG_BUFFER_SIZE 256 - static char logBuf[LOG_BUFFER_SIZE]; - static struct log_output_control_block logControlBlock; - static struct log_output logOutput = { - .func = outputFunc, - .buf = logBuf, - .size = LOG_BUFFER_SIZE, - .control_block = &logControlBlock, - }; - -// Helper to get the log source name from a log message -ATTR_UNUSED static const char *getLogSourceName(struct log_msg *msg) { +static char logBuf[LOG_BUFFER_SIZE]; +static struct log_output_control_block logControlBlock; +static struct log_output logOutput = { + .func = outputFunc, + .buf = logBuf, + .size = LOG_BUFFER_SIZE, + .control_block = &logControlBlock, +}; + +// --- Helpers --- + +static const char *getLogSourceName(struct log_msg *msg) +{ const void *source = log_msg_get_source(msg); if (source == NULL) { return "unknown"; } - // The source pointer is a log_source_const_data struct which has a name field const struct log_source_const_data *src_data = (const struct log_source_const_data *)source; return src_data->name ? src_data->name : "unnamed"; } -static void processLog(const struct log_backend *const backend, union log_msg_generic *msg) { - proxy_log_context_t outputs = (proxy_log_context_t){ - .outputToStatusBuffer = false, - .outputToUsbBuffer = false, - .outputToOled = false, - }; - - if (WormCfg->UsbLogEnabled) { - outputs.outputToUsbBuffer = true; - outputs.outputToOled = true; - } +// --- Log backend API --- - if (ProxyLog_IsInPanicMode) { - outputs.outputToStatusBuffer = true; - } +static void proxyProcess(const struct log_backend *const backend, union log_msg_generic *msg) +{ + shell_sinks_t sinks = ShellConfig_GetLogSinks(); if (WormCfg->devMode) { - // PoC: Extract log source and level information uint8_t level = log_msg_get_level(&msg->log); const char *sourceName = getLogSourceName(&msg->log); - if ( level >= LOG_LEVEL_WRN && strcmp(sourceName, "c2usb") == 0) { - outputs.outputToStatusBuffer = true; + if (level >= LOG_LEVEL_WRN && strcmp(sourceName, "c2usb") == 0) { + sinks.toStatusBuffer = true; } } - if (outputs.outputToStatusBuffer || outputs.outputToUsbBuffer || outputs.outputToOled) { - log_output_ctx_set(&logOutput, &outputs); + if (sinks.toStatusBuffer || sinks.toUsbBuffer || sinks.toOled) { + log_output_ctx_set(&logOutput, &sinks); uint8_t flags = LOG_OUTPUT_FLAG_CRLF_LFONLY; log_output_msg_process(&logOutput, &msg->log, flags); } } -void init(const struct log_backend *const backend) {}; -int format_set(const struct log_backend *const backend, uint32_t log_type) { return 0; }; -void notify(const struct log_backend *const backend, enum log_backend_evt event, union log_backend_evt_arg *arg) {}; -static int is_ready(const struct log_backend *const backend) { return 0; } - -static struct log_backend_api proxyApi = (struct log_backend_api) { - .process = processLog, - .dropped = NULL, - .panic = panic, - .init = init, - .is_ready = is_ready, - .format_set = format_set, - .notify = notify, -}; +static void proxyPanic(const struct log_backend *const backend) +{ + ShellConfig_ActivatePanicMode(); +} -#define PROXY_LOG_BACKEND_AUTOSTART true +static void proxyInit(const struct log_backend *const backend) +{ +} -LOG_BACKEND_DEFINE(logProxy, proxyApi, PROXY_LOG_BACKEND_AUTOSTART); +static int proxyIsReady(const struct log_backend *const backend) +{ + return 0; +} -void InitProxyLogBackend(void) { -#if !PROXY_LOG_BACKEND_AUTOSTART - log_init(); +static int proxyFormatSet(const struct log_backend *const backend, uint32_t log_type) +{ + return 0; +} - const struct log_backend *backend = log_backend_get_by_name("logProxy"); +static void proxyNotify(const struct log_backend *const backend, enum log_backend_evt event, union log_backend_evt_arg *arg) +{ +} - log_output_ctx_set(&logOutput, backend->cb->ctx); +static const struct log_backend_api proxyApi = { + .process = proxyProcess, + .dropped = NULL, + .panic = proxyPanic, + .init = proxyInit, + .is_ready = proxyIsReady, + .format_set = proxyFormatSet, + .notify = proxyNotify, +}; - log_backend_activate(backend, backend->cb->ctx); -#endif -} +LOG_BACKEND_DEFINE(UhkLog, proxyApi, true); diff --git a/device/src/proxy_log_backend.h b/device/src/proxy_log_backend.h deleted file mode 100644 index 5512691c3..000000000 --- a/device/src/proxy_log_backend.h +++ /dev/null @@ -1,21 +0,0 @@ -#ifndef __PROXY_LOG_BACKEND_H__ -#define __PROXY_LOG_BACKEND_H__ - -// Includes: - - #include - #include - -// Macros: - -// Typedefs: - -// Variables: - - extern bool ProxyLog_IsInPanicMode; - -// Functions: - - void InitProxyLogBackend(void); - -#endif diff --git a/device/src/shell.h b/device/src/shell.h index 19418a0dc..52ead4788 100644 --- a/device/src/shell.h +++ b/device/src/shell.h @@ -21,10 +21,6 @@ extern shell_t Shell; // Functions: -extern void UninitShell(void); -extern void ReinitShell(void); extern void InitShellCommands(void); -extern void Shell_Execute(const char *cmd, const char *source); -extern void Shell_WaitUntilInitialized(void); #endif // SHELL_H__ diff --git a/device/src/shell_backend_usb.c b/device/src/shell/shell_backend_usb.c similarity index 92% rename from device/src/shell_backend_usb.c rename to device/src/shell/shell_backend_usb.c index 7f4635b1d..ce0d13ba4 100644 --- a/device/src/shell_backend_usb.c +++ b/device/src/shell/shell_backend_usb.c @@ -3,10 +3,6 @@ #include #include -#ifdef CONFIG_SHELL_BACKEND_SERIAL -#include -#endif - static const struct shell *get_shell_backend_by_name(const char *name) { size_t backend_count = shell_backend_count_get(); @@ -21,7 +17,7 @@ static const struct shell *get_shell_backend_by_name(const char *name) void ShellBackend_Exec(const char *cmd, const char* source) { - const struct shell *sh = get_shell_backend_by_name("shell_uart"); + const struct shell *sh = get_shell_backend_by_name("UhkShell"); if (sh == NULL) { printk("Shell backend not available, cannot execute command: '%s'\n", cmd); diff --git a/device/src/shell_backend_usb.h b/device/src/shell/shell_backend_usb.h similarity index 100% rename from device/src/shell_backend_usb.h rename to device/src/shell/shell_backend_usb.h diff --git a/device/src/shell.c b/device/src/shell/shell_commands.c similarity index 82% rename from device/src/shell.c rename to device/src/shell/shell_commands.c index 729450b60..76dfab04e 100644 --- a/device/src/shell.c +++ b/device/src/shell/shell_commands.c @@ -5,32 +5,22 @@ #include "keyboard/leds.h" #include "keyboard/oled/oled.h" #include "logger.h" -#include "proxy_log_backend.h" #include "usb_log_buffer.h" #include "usb/usb.h" -#include #include #include -#include "bt_conn.h" -#include "keyboard/charger.h" #include "ledmap.h" -#include "event_scheduler.h" #include "host_connection.h" #include "thread_stats.h" #include "trace.h" #include "usb_compatibility.h" #include "mouse_keys.h" #include "config_manager.h" -#include -#include -#include #include "connections.h" #include "logger_priority.h" -#include "pin_wiring.h" -#include "device.h" -#include "logger.h" #include "shell_backend_usb.h" -#include "stubs.h" +#include "sinks.h" +#include "wormhole.h" #include #include @@ -42,24 +32,6 @@ shell_t Shell = { .sdbState = 1, }; -void list_backends_by_iteration(void) { - const struct shell *shell; - size_t idx = 0; - size_t backendCount = shell_backend_count_get(); - - printk("Available shell backends:\n"); - for (size_t i = 0; i < backendCount; i++) { - shell = shell_backend_get(idx); - printk("- Backend %zu: %s\n", idx, shell->name); - idx++; - } -} - -void Shell_Execute(const char *cmd, const char *source) { - ShellBackend_Exec(cmd, source); - return; -} - static int cmd_uhk_keylog(const struct shell *shell, size_t argc, char *argv[]) { if (argc == 1) { @@ -367,9 +339,9 @@ static int cmd_uhk_logPriority(const struct shell *shell, size_t argc, char *arg static int cmd_uhk_logs(const struct shell *shell, size_t argc, char *argv[]) { - if (argc == 1 || argv[1][0] == '1') { + if (argc > 1 && argv[1][0] == '1') { WormCfg->UsbLogEnabled = true; - } else if (argc == 1 || argv[1][0] == '0') { + } else if (argc > 1 && argv[1][0] == '0') { WormCfg->UsbLogEnabled = false; } @@ -382,99 +354,46 @@ static int cmd_uhk_logs(const struct shell *shell, size_t argc, char *argv[]) return 0; } -static int cmd_uhk_snaplog(const struct shell *shell, size_t argc, char *argv[]) +static int cmd_uhk_useShellSinks(const struct shell *shell, size_t argc, char *argv[]) { - UsbLogBuffer_SnapToStatusBuffer(); - printk("Log snapped to status buffer.\n"); - return 0; -} - -void Shell_WaitUntilInitialized(void) { - const struct shell *sh = shell_backend_uart_get_ptr(); - if (sh) { - // if we set levels before shell is ready, the shell will mercilessly overwrite them - while (!shell_ready(sh)) { - k_msleep(10); - } + if (argc == 1) { + shell_fprintf(shell, SHELL_NORMAL, "%i\n", ShellConfig_UseShellSinks ? 1 : 0); + } else { + ShellConfig_UseShellSinks = argv[1][0] == '1'; } + return 0; } -static int reinitShell(const struct device *const dev) +static int cmd_uhk_logStatus(const struct shell *shell, size_t argc, char *argv[]) { - int ret; - const struct shell *sh = NULL; - - sh = shell_backend_uart_get_ptr(); - - if (!sh) { - LogS("Shell backend not found\n"); - return -ENODEV; - } - - if (!dev) { - LogS("Shell device is NULL\n"); - return -ENODEV; - } - const struct device *const dev2 = DEVICE_DT_GET(DT_CHOSEN(zephyr_shell_uart)); - - // (Re)initialize the shell - bool log_backend = true; - uint32_t level = 4U; - ret = shell_init(sh, dev2, sh->ctx->cfg.flags, log_backend, level); - if (ret < 0) { - LogS("Shell init failed: %d\n", ret); - return ret; - } - - k_sleep(K_MSEC(10)); - - // Start the shell - ret = shell_start(sh); - if (ret < 0) { - LogS("Shell start failed: %d\n", ret); - return ret; - } - - Shell_WaitUntilInitialized(); + uint16_t usbBufferFill, usbBufferSize; + UsbLogBuffer_GetFill(&usbBufferFill, &usbBufferSize); + printk("Usb logging enabled: %d\n", WormCfg->UsbLogEnabled); + printk("Has log: %d\n", UsbLogBuffer_HasLog); + printk("Usb log buffer fill: %d / %d\n", usbBufferFill, usbBufferSize); + printk("UseShellSinks: %d\n", ShellConfig_UseShellSinks ? 1 : 0); return 0; } -static bool shellUninitialized = false; - -static void shell_uninit_cb(const struct shell *sh, int res) { - shellUninitialized = true; -} - -void UninitShell(void) +static int cmd_uhk_snaplog(const struct shell *shell, size_t argc, char *argv[]) { - const struct shell *sh = NULL; - - sh = shell_backend_uart_get_ptr(); - shellUninitialized = false; - - shell_uninit(sh, shell_uninit_cb); - - while (!shellUninitialized) { - k_sleep(K_MSEC(10)); - } -} - -void ReinitShell(void) { - if (!DEVICE_IS_UHK80_RIGHT) { - return; - } - - if (PinWiringConfig->device_uart_shell == NULL) { - return; - } else { - reinitShell(PinWiringConfig->device_uart_shell->device); - } + UsbLogBuffer_SnapToStatusBuffer(); + printk("Log snapped to status buffer.\n"); + return 0; } void InitShellCommands(void) { + SHELL_STATIC_SUBCMD_SET_CREATE(uhk_log_cmds, + SHELL_CMD_ARG(usbLog, NULL, "Set/get USB log enabled", cmd_uhk_logs, 1, 1), + SHELL_CMD_ARG(priority, NULL, "set log priority", cmd_uhk_logPriority, 2, 0), + SHELL_CMD_ARG(snapshot, NULL, "Snap log buffer to status buffer", cmd_uhk_snaplog, 1, 0), + SHELL_CMD_ARG(status, NULL, "print log status overview", cmd_uhk_logStatus, 1, 0), + SHELL_CMD_ARG(useShellSinks, NULL, "get/set shell sinks mode", cmd_uhk_useShellSinks, 1, 1), + SHELL_SUBCMD_SET_END); + SHELL_STATIC_SUBCMD_SET_CREATE(uhk_cmds, SHELL_CMD_ARG(keylog, NULL, "get/set key logging", cmd_uhk_keylog, 1, 1), #if !DEVICE_IS_UHK_DONGLE @@ -502,13 +421,10 @@ void InitShellCommands(void) SHELL_CMD_ARG(threads, NULL, "list thread statistics", cmd_uhk_threads, 1, 0), SHELL_CMD_ARG(trace, NULL, "lists minimalistic event trace", cmd_uhk_trace, 1, 0), SHELL_CMD_ARG(mouseMultipliers, NULL, "print mouse multipliers", cmd_uhk_mouseMultipliers, 1, 0), - SHELL_CMD_ARG(logPriority, NULL, "set log priority", cmd_uhk_logPriority, 2, 0), - SHELL_CMD_ARG(logs, NULL, "Set/get proxy log enabled", cmd_uhk_logs, 1, 1), - SHELL_CMD_ARG(snaplog, NULL, "Snap log buffer to status buffer", cmd_uhk_snaplog, 1, 0), + SHELL_CMD(log, &uhk_log_cmds, "Log management", NULL), SHELL_CMD_ARG(shells, NULL, "list available shell backends", cmd_uhk_shells, 1, 0), SHELL_CMD_ARG(irqs, NULL, "list enabled IRQs and their priorities", cmd_uhk_irqs, 1, 0), SHELL_SUBCMD_SET_END); SHELL_CMD_REGISTER(uhk, &uhk_cmds, "UHK commands", NULL); } - diff --git a/device/src/shell/shell_transport_uhk.c b/device/src/shell/shell_transport_uhk.c new file mode 100644 index 000000000..21ddad3fe --- /dev/null +++ b/device/src/shell/shell_transport_uhk.c @@ -0,0 +1,361 @@ +#include "shell_transport_uhk.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include "logger.h" +#include "usb_log_buffer.h" +#include "wormhole.h" +#include "config_manager.h" +#include "sinks.h" +#include "macros/status_buffer.h" + +#define LOG_MODULE_NAME shell_transport_uhk +LOG_MODULE_REGISTER(shell_transport_uhk); + +// --- Configuration --- + +#define UART_RX_BUF_COUNT 4 +#define UART_RX_BUF_SIZE 16 +#define UART_RX_TOTAL_SIZE (UART_RX_BUF_COUNT * \ + (UART_RX_BUF_SIZE + UART_ASYNC_RX_BUF_OVERHEAD)) + +// --- UART transport state --- + +enum vt100_state { + VT100_NORMAL, + VT100_ESC_START, + VT100_CSI_PARAMS, +}; + +struct uart_transport_data { + const struct device *dev; + shell_transport_handler_t handler; + void *context; + bool blocking_tx; + bool uartEnabled; + + // TX + struct k_sem tx_sem; + + // VT100 stripping state + enum vt100_state vt100State; + + // Async RX + struct uart_async_rx async_rx; + struct uart_async_rx_config async_rx_config; + atomic_t pending_rx_req; + uint8_t rx_data[UART_RX_TOTAL_SIZE]; +}; + +static struct uart_transport_data uartTransportData; + +// --- UART async callbacks --- + +static int uartRxEnable(const struct device *dev, uint8_t *buf, size_t len) +{ + return uart_rx_enable(dev, buf, len, 10000); +} + +static void uartAsyncCallback(const struct device *dev, struct uart_event *evt, void *user_data) +{ + struct uart_transport_data *data = (struct uart_transport_data *)user_data; + + switch (evt->type) { + case UART_TX_DONE: + k_sem_give(&data->tx_sem); + break; + case UART_RX_RDY: + uart_async_rx_on_rdy(&data->async_rx, evt->data.rx.buf, evt->data.rx.len); + data->handler(SHELL_TRANSPORT_EVT_RX_RDY, data->context); + break; + case UART_RX_BUF_REQUEST: + { + uint8_t *buf = uart_async_rx_buf_req(&data->async_rx); + size_t len = uart_async_rx_get_buf_len(&data->async_rx); + + if (buf) { + int err = uart_rx_buf_rsp(dev, buf, len); + if (err < 0) { + uart_async_rx_on_buf_rel(&data->async_rx, buf); + } + } else { + atomic_inc(&data->pending_rx_req); + } + break; + } + case UART_RX_BUF_RELEASED: + uart_async_rx_on_buf_rel(&data->async_rx, evt->data.rx_buf.buf); + break; + case UART_RX_DISABLED: + break; + default: + break; + } +} + +// --- Output sink routing --- + +static size_t stripVt100(struct uart_transport_data *td, const uint8_t *in, size_t inLen, uint8_t *out, size_t outSize) +{ + size_t outLen = 0; + + for (size_t i = 0; i < inLen; i++) { + uint8_t c = in[i]; + + switch (td->vt100State) { + case VT100_NORMAL: + if (c == 0x1B) { + td->vt100State = VT100_ESC_START; + } else { + if (outLen < outSize) { + out[outLen++] = c; + } + } + break; + case VT100_ESC_START: + if (c == '[') { + td->vt100State = VT100_CSI_PARAMS; + } else { + td->vt100State = VT100_NORMAL; + } + break; + case VT100_CSI_PARAMS: + if (c >= 0x40 && c <= 0x7E) { + td->vt100State = VT100_NORMAL; + } + break; + } + } + + return outLen; +} + +static void outputToSinks(const shell_sinks_t *sinks, struct uart_transport_data *td, const uint8_t *data, size_t length) +{ + if (!sinks->toUsbBuffer && !sinks->toOled && !sinks->toStatusBuffer) { + return; + } + + uint8_t stripped[48]; + size_t strippedLen = stripVt100(td, data, length, stripped, sizeof(stripped)); + + if (strippedLen == 0) { + return; + } + + if (sinks->toUsbBuffer) { + UsbLogBuffer_Print(stripped, strippedLen); + } + + if (sinks->toOled) { + LogO("%.*s", (int)strippedLen, stripped); + } + + if (sinks->toStatusBuffer) { + Macros_SanitizedPut((const char *)stripped, (const char *)stripped + strippedLen); + } +} + +// --- UART TX helpers --- + +static int uartTxBlocking(struct uart_transport_data *data, const uint8_t *buf, size_t length) +{ + for (size_t i = 0; i < length; i++) { + uart_poll_out(data->dev, buf[i]); + } + return 0; +} + +static int uartTxAsync(struct uart_transport_data *data, const uint8_t *buf, size_t length) +{ + int err = uart_tx(data->dev, buf, length, SYS_FOREVER_US); + if (err < 0) { + return err; + } + + return k_sem_take(&data->tx_sem, K_FOREVER); +} + +static int uartTx(struct uart_transport_data *data, const uint8_t *buf, size_t length) +{ + if (data->blocking_tx) { + return uartTxBlocking(data, buf, length); + } else { + return uartTxAsync(data, buf, length); + } +} + +// --- shell_transport_api implementation --- + +static int uartTransportInit(const struct shell_transport *transport, + const void *config, + shell_transport_handler_t evt_handler, + void *context) +{ + struct uart_transport_data *data = (struct uart_transport_data *)transport->ctx; + + data->dev = (const struct device *)config; + data->handler = evt_handler; + data->context = context; + data->blocking_tx = false; + data->uartEnabled = true; + + data->async_rx_config = (struct uart_async_rx_config){ + .buffer = data->rx_data, + .length = UART_RX_TOTAL_SIZE, + .buf_cnt = UART_RX_BUF_COUNT, + }; + + k_sem_init(&data->tx_sem, 0, 1); + + int err = uart_async_rx_init(&data->async_rx, &data->async_rx_config); + __ASSERT_NO_MSG(err == 0); + + uint8_t *buf = uart_async_rx_buf_req(&data->async_rx); + + err = uart_callback_set(data->dev, uartAsyncCallback, (void *)data); + __ASSERT_NO_MSG(err == 0); + + err = uartRxEnable(data->dev, buf, uart_async_rx_get_buf_len(&data->async_rx)); + __ASSERT_NO_MSG(err == 0); + + return 0; +} + +static int uartTransportUninit(const struct shell_transport *transport) +{ + struct uart_transport_data *data = (struct uart_transport_data *)transport->ctx; + + data->uartEnabled = false; + + if (data->dev) { + uart_rx_disable(data->dev); + } + + return 0; +} + +static int uartTransportEnable(const struct shell_transport *transport, bool blocking_tx) +{ + struct uart_transport_data *data = (struct uart_transport_data *)transport->ctx; + + data->blocking_tx = blocking_tx; + + return 0; +} + +static int uartTransportWrite(const struct shell_transport *transport, + const void *buf, size_t length, size_t *cnt) +{ + struct uart_transport_data *data = (struct uart_transport_data *)transport->ctx; + const uint8_t *bytes = (const uint8_t *)buf; + + // Resolve and route to output sinks + shell_sinks_t sinks = ShellConfig_GetShellSinks(); + outputToSinks(&sinks, data, bytes, length); + + // Send to UART + if (data->uartEnabled) { + int err = uartTx(data, bytes, length); + if (err < 0) { + *cnt = 0; + return err; + } + } + + *cnt = length; + data->handler(SHELL_TRANSPORT_EVT_TX_RDY, data->context); + + return 0; +} + +static int uartTransportRead(const struct shell_transport *transport, + void *buf, size_t length, size_t *cnt) +{ + struct uart_transport_data *data = (struct uart_transport_data *)transport->ctx; + struct uart_async_rx *async_rx = &data->async_rx; + + uint8_t *rxBuf; + size_t blen = uart_async_rx_data_claim(async_rx, &rxBuf, length); + + memcpy(buf, rxBuf, blen); + bool buf_available = uart_async_rx_data_consume(async_rx, blen); + *cnt = blen; + + if (data->pending_rx_req && buf_available) { + uint8_t *newBuf = uart_async_rx_buf_req(async_rx); + size_t newLen = uart_async_rx_get_buf_len(async_rx); + int err; + + __ASSERT_NO_MSG(newBuf != NULL); + atomic_dec(&data->pending_rx_req); + err = uart_rx_buf_rsp(data->dev, newBuf, newLen); + // If it is too late and RX is disabled then re-enable it. + if (err < 0) { + if (err == -EACCES) { + data->pending_rx_req = 0; + err = uartRxEnable(data->dev, newBuf, newLen); + } else { + return err; + } + } + } + + return 0; +} + +// --- Transport API struct --- + +static const struct shell_transport_api uartTransportApi = { + .init = uartTransportInit, + .uninit = uartTransportUninit, + .enable = uartTransportEnable, + .write = uartTransportWrite, + .read = uartTransportRead, +}; + +struct shell_transport ShellUartTransport = { + .api = &uartTransportApi, + .ctx = &uartTransportData, +}; + +// --- Public UART transport uninit/reinit --- + +void ShellUartTransport_Uninit(void) +{ + struct uart_transport_data *data = &uartTransportData; + + if (data->dev) { + uart_rx_disable(data->dev); + } + + data->uartEnabled = false; +} + +void ShellUartTransport_Reinit(void) +{ + struct uart_transport_data *data = &uartTransportData; + + if (!data->dev) { + return; + } + + // Defensive: force-disable UART RX to handle stale state after soft reset + uart_rx_disable(data->dev); + + // Re-register callback and re-enable RX + int err = uart_callback_set(data->dev, uartAsyncCallback, (void *)data); + __ASSERT_NO_MSG(err == 0); + + uint8_t *buf = uart_async_rx_buf_req(&data->async_rx); + err = uartRxEnable(data->dev, buf, uart_async_rx_get_buf_len(&data->async_rx)); + __ASSERT_NO_MSG(err == 0); + + data->uartEnabled = true; +} diff --git a/device/src/shell/shell_transport_uhk.h b/device/src/shell/shell_transport_uhk.h new file mode 100644 index 000000000..4e4c7d31d --- /dev/null +++ b/device/src/shell/shell_transport_uhk.h @@ -0,0 +1,17 @@ +#ifndef __SHELL_TRANSPORT_UHK_H__ +#define __SHELL_TRANSPORT_UHK_H__ + +// Includes: + + #include + +// Variables: + + extern struct shell_transport ShellUartTransport; + +// Functions: + + void ShellUartTransport_Uninit(void); + void ShellUartTransport_Reinit(void); + +#endif diff --git a/device/src/shell/shell_uhk.c b/device/src/shell/shell_uhk.c new file mode 100644 index 000000000..89854de0b --- /dev/null +++ b/device/src/shell/shell_uhk.c @@ -0,0 +1,75 @@ +#include "shell_uhk.h" +#include "shell_transport_uhk.h" +#include +#include +#include +#include +#include + +// --- Configuration --- + +#define SHELL_LOG_QUEUE_SIZE 512 +#define SHELL_LOG_QUEUE_TIMEOUT 1000 + +// --- Shell instance --- + +SHELL_DEFINE(UhkShell, CONFIG_SHELL_PROMPT_RTT, &ShellUartTransport, + SHELL_LOG_QUEUE_SIZE, + SHELL_LOG_QUEUE_TIMEOUT, + SHELL_FLAG_OLF_CRLF); + +// --- Public API --- + +const struct shell *ShellUhk_GetShellPtr(void) +{ + return &UhkShell; +} + +int ShellUhk_Init(void) +{ + const struct device *const dev = DEVICE_DT_GET(DT_CHOSEN(zephyr_shell_uart)); + bool log_backend = true; + uint32_t level = CONFIG_LOG_MAX_LEVEL; + static const struct shell_backend_config_flags cfg_flags = + SHELL_DEFAULT_BACKEND_CONFIG_FLAGS; + + if (!device_is_ready(dev)) { + return -ENODEV; + } + + shell_init(&UhkShell, dev, cfg_flags, log_backend, level); + + return 0; +} + +SYS_INIT(ShellUhk_Init, POST_KERNEL, CONFIG_APPLICATION_INIT_PRIORITY); + +void Shell_WaitUntilInitialized(void) +{ + const struct shell *sh = ShellUhk_GetShellPtr(); + if (sh) { + // if we set levels before shell is ready, the shell will mercilessly overwrite them + while (!shell_ready(sh)) { + k_msleep(10); + } + } +} + +void Shell_Execute(const char *cmd, const char *source) +{ + const struct shell *sh = ShellUhk_GetShellPtr(); + + if (sh == NULL) { + printk("Shell backend not available, cannot execute command: '%s'\n", cmd); + return; + } + + /* Ensure terminal width is set to prevent division by zero errors */ + if (sh->ctx != NULL && sh->ctx->vt100_ctx.cons.terminal_wid == 0) { + struct shell *sh_mutable = (struct shell *)sh; + sh_mutable->ctx->vt100_ctx.cons.terminal_wid = 80; + } + + printk("Executing following command from %s in %s: '%s'\n", source ? source : "unknown", sh->name, cmd); + shell_execute_cmd(sh, cmd); +} diff --git a/device/src/shell/shell_uhk.h b/device/src/shell/shell_uhk.h new file mode 100644 index 000000000..7a3b6d0e4 --- /dev/null +++ b/device/src/shell/shell_uhk.h @@ -0,0 +1,15 @@ +#ifndef __SHELL_UHK_H__ +#define __SHELL_UHK_H__ + +// Includes: + + #include + +// Functions: + + const struct shell *ShellUhk_GetShellPtr(void); + int ShellUhk_Init(void); + void Shell_WaitUntilInitialized(void); + void Shell_Execute(const char *cmd, const char *source); + +#endif diff --git a/device/src/shell/sinks.c b/device/src/shell/sinks.c new file mode 100644 index 000000000..59ada2fa2 --- /dev/null +++ b/device/src/shell/sinks.c @@ -0,0 +1,51 @@ +#include "sinks.h" +#include "wormhole.h" +#include "macros/status_buffer.h" +#include "trace.h" +#include "config_manager.h" + +bool ShellConfig_IsInPanicMode = false; + +bool ShellConfig_UseShellSinks = false; + +static shell_sinks_t emptyConfig() { + return (shell_sinks_t){ + .toUsbBuffer = false, + .toOled = false, + .toStatusBuffer = false, + }; +} + +static shell_sinks_t activeConfig() { + return (shell_sinks_t){ + .toUsbBuffer = WormCfg->UsbLogEnabled, + .toOled = WormCfg->UsbLogEnabled, + .toStatusBuffer = ShellConfig_IsInPanicMode, + }; +} + + + +void ShellConfig_ActivatePanicMode(void) +{ + if (!ShellConfig_IsInPanicMode) { + StateWormhole_Open(); + StateWormhole.persistStatusBuffer = true; + + ShellConfig_IsInPanicMode = true; + + MacroStatusBuffer_Validate(); + printk("===== PANIC =====\n"); + Trace_Print(LogTarget_ErrorBuffer, "crash/panic"); + } +} + +shell_sinks_t ShellConfig_GetShellSinks(void) +{ + return ShellConfig_UseShellSinks ? activeConfig() : emptyConfig(); +} + +shell_sinks_t ShellConfig_GetLogSinks(void) +{ + return ShellConfig_UseShellSinks ? emptyConfig() : activeConfig(); +} diff --git a/device/src/shell/sinks.h b/device/src/shell/sinks.h new file mode 100644 index 000000000..66bba23df --- /dev/null +++ b/device/src/shell/sinks.h @@ -0,0 +1,27 @@ +#ifndef __SINKS_H__ +#define __SINKS_H__ + +// Includes: + + #include + +// Typedefs: + + typedef struct { + bool toUsbBuffer; + bool toOled; + bool toStatusBuffer; + } shell_sinks_t; + +// Variables: + + extern bool ShellConfig_IsInPanicMode; + extern bool ShellConfig_UseShellSinks; + +// Functions: + + void ShellConfig_ActivatePanicMode(void); + shell_sinks_t ShellConfig_GetShellSinks(void); + shell_sinks_t ShellConfig_GetLogSinks(void); + +#endif diff --git a/doc-dev/other/shell_backends.md b/doc-dev/other/shell_backends.md new file mode 100644 index 000000000..340caa52d --- /dev/null +++ b/doc-dev/other/shell_backends.md @@ -0,0 +1,738 @@ +# Zephyr Shell, Shell Backends, and Logging Backends + +This document explains how Zephyr's shell subsystem, shell backends, and logging subsystem interact — with a focus on log filtering, because understanding the multiple filtering stages is essential for debugging "why does my message appear on one backend but not another?" + +## Helicopter View + +### Ownership Structure + +```mermaid +graph TD + subgraph "UhkShell Instance (struct shell)" + TRANSPORT["UHK UART Transport\n(struct shell_transport)\nVT100 stripping + sink routing"] + SHELL_LB["Shell Log Backend\n(struct shell_log_backend)"] + LOG_BACKEND_S["Log Backend\n(struct log_backend)"] + PRIV_BUF["Private MPSC Buffer"] + SHELL_LB --> LOG_BACKEND_S + SHELL_LB --> PRIV_BUF + end + + subgraph "Custom Log Backend" + LOG_BACKEND_C["Log Backend\n(struct log_backend)\nUhkLog"] + end + + subgraph "Sinks (shell_sinks_t)" + USB_BUF["USB Log Buffer"] + OLED["OLED Console"] + STATUS["Status Buffer"] + end + + LOG_CORE["Central Log\nProcessing Thread"] + LOG_CORE -.->|"iterates all\nlog_backend instances"| LOG_BACKEND_S + LOG_CORE -.->|"iterates all\nlog_backend instances"| LOG_BACKEND_C + + TRANSPORT -->|"ShellConfig_GetShellSinks()"| USB_BUF + TRANSPORT -->|"ShellConfig_GetShellSinks()"| OLED + TRANSPORT -->|"ShellConfig_GetShellSinks()"| STATUS + + LOG_BACKEND_C -->|"ShellConfig_GetLogSinks()"| USB_BUF + LOG_BACKEND_C -->|"ShellConfig_GetLogSinks()"| OLED + LOG_BACKEND_C -->|"ShellConfig_GetLogSinks()"| STATUS + + style TRANSPORT fill:#bdf,color:#000 + style SHELL_LB fill:#bfd,color:#000 + style LOG_BACKEND_S fill:#fdb,color:#000 + style LOG_BACKEND_C fill:#fdb,color:#000 + style LOG_CORE fill:#ddd,color:#000 +``` + +The **UhkShell** instance owns a custom **UHK UART transport** (byte I/O with VT100 stripping and output sink routing) and a **shell log backend** (which wraps a `log_backend` + private buffer). The **UhkLog** backend is standalone — the central log thread discovers both via the same linker section. Both the transport and UhkLog route output to **sinks** (USB buffer, OLED, status buffer) via a shared configuration. + +### Path of Shell Command Output + +```mermaid +graph LR + USER["User types\n'uhk charger'"] --> TRANSPORT_R["UHK UART Transport\n.read()"] + TRANSPORT_R --> SHELL_THREAD["Shell Thread\n(parse & execute)"] + SHELL_THREAD --> HANDLER["Command Handler\nshell_print()"] + HANDLER --> TRANSPORT_W["UHK UART Transport\n.write()"] + TRANSPORT_W --> SINKS["Output Sinks\n(if useShellSinks)"] + TRANSPORT_W --> HW["UART Hardware"] + + style SHELL_THREAD fill:#bdf,color:#000 +``` + +Shell command output goes **directly** from the command handler through the UHK UART transport. The transport both sends to the physical UART and routes to output sinks (USB buffer, OLED, status buffer) after stripping VT100 escape sequences. It **never** passes through the central logging core. + +### Path of a LOG_INF() Message to a Shell + +```mermaid +graph LR + APP["LOG_INF('hello')"] --> FILTER["Compile-time\n& runtime\nfilters"] + FILTER --> CENTRAL_BUF["Central\nMPSC Buffer"] + CENTRAL_BUF --> LOG_THREAD["Log Processing\nThread"] + LOG_THREAD -->|"per-backend\nslot check"| SHELL_LB["Shell Log Backend\n.process()"] + SHELL_LB -->|"memcpy"| PRIV_BUF["Shell's Private\nMPSC Buffer"] + PRIV_BUF -->|"signal"| SHELL_THREAD["Shell Thread\n(format & write)"] + SHELL_THREAD --> TRANSPORT["UHK UART Transport\n.write()"] + TRANSPORT --> HW["UART / Sinks"] + + style LOG_THREAD fill:#ddd,color:#000 + style SHELL_THREAD fill:#bdf,color:#000 + style SHELL_LB fill:#bfd,color:#000 +``` + +A `LOG_INF()` goes through two threads: the **central log thread** (filter + copy to private buffer) and the **shell thread** (format + VT100 line management + write). The shell thread erases the current command line before printing the log message and redraws it after. + +Note: `printk()` takes this same path (when `CONFIG_LOG_PRINTK=y`, the default), but with a special level that bypasses all filters. + +## Zephyr Concepts + +### struct shell — A Shell Instance + +A `struct shell` is a **complete, self-contained interactive terminal**. It owns: + +- A **transport** (`struct shell_transport`) — the byte-level I/O channel (UART, RTT, BLE NUS, ...) +- A **dedicated thread** — each shell instance gets its own `k_thread` with its own stack +- A **log backend** (`struct shell_log_backend`) — makes this shell instance receive log messages +- Runtime state: command buffer, cursor, VT100 terminal state, prompt, command history + +Shell instances are created at compile time by the `SHELL_DEFINE` macro. Each transport backend (UART, RTT, BLE NUS) creates one instance. + +### Shell Transport (aka "Shell Backend") + +A `struct shell_transport` is the **byte-level I/O driver** behind a shell instance. It implements the `shell_transport_api` interface: + +| Method | Purpose | +|--------|---------| +| `init()` | Initialize, register event callback | +| `enable()` | Start I/O | +| `write()` | Send bytes to the hardware | +| `read()` | Receive bytes from the hardware | +| `uninit()` | Tear down | + +The transport signals the shell via a callback with `SHELL_TRANSPORT_EVT_RX_RDY` (data available to read) and `SHELL_TRANSPORT_EVT_TX_RDY` (transmit complete). These raise `k_poll_signal`s that wake the shell thread. + +Zephyr provides concrete implementations: UART (`shell_uart.c`), RTT (`shell_rtt.c`), BLE NUS (`shell_bt_nus.c`), Telnet, etc. The UHK firmware uses a **custom UART transport** (`shell_transport_uhk.c`) instead of Zephyr's standard one. + +### Log Backend + +A `struct log_backend` is a **consumer of log messages**. It implements the `log_backend_api` interface: + +| Method | Purpose | +|--------|---------| +| `process()` | Receive and handle a log message | +| `panic()` | Enter panic mode (switch to synchronous output) | +| `init()` | Initialize | +| `is_ready()` | Check if backend can accept messages | +| `dropped()` | Notification that messages were dropped | + +Log backends are registered at compile time via `LOG_BACKEND_DEFINE` into a linker section. The logging core iterates this section to dispatch messages. + +**Key distinction:** A "shell backend" (= shell transport, byte-level I/O) and a "log backend" (= log message consumer) are **different concepts**. But each shell instance **also creates a log backend** (via `Z_SHELL_LOG_BACKEND_DEFINE` inside `SHELL_DEFINE`), so every shell is simultaneously both. + +### How They Relate + +```mermaid +graph TB + subgraph "Shell Instance (struct shell)" + THREAD["Dedicated shell thread"] + CTX["Shell context (cmd buffer, cursor, VT100)"] + TRANSPORT["Shell transport (struct shell_transport)"] + SHELL_LB["Shell's log backend (struct shell_log_backend)"] + PRIV_BUF["Private MPSC log buffer"] + end + + TRANSPORT -->|"write()"| HW["Hardware (UART/RTT/BLE)"] + HW -->|"RX_RDY signal"| TRANSPORT + TRANSPORT --> THREAD + THREAD -->|"processes commands"| CTX + THREAD -->|"drains log messages"| PRIV_BUF + + LOG_THREAD["Central log processing thread"] -->|"copies messages into"| PRIV_BUF + PRIV_BUF -->|"LOG_MSG signal wakes"| THREAD + THREAD -->|"formats & outputs via"| TRANSPORT +``` + +Each shell instance is created by `SHELL_DEFINE`, which expands to: +1. `K_KERNEL_STACK_DEFINE` — allocate a thread stack +2. `Z_SHELL_LOG_BACKEND_DEFINE` — create a `LOG_BACKEND_DEFINE` + private MPSC buffer +3. Wire everything together into `struct shell` + +## Architecture Overview + +```mermaid +graph TB + subgraph "Application Code" + LOG["LOG_INF() / LOG_WRN() / LOG_ERR() / LOG_DBG()"] + PRINTK["printk()"] + LOGFN["Log() / LogU() / LogO() / LogS()
(UHK custom functions)"] + end + + subgraph "Zephyr Logging Core" + CT["Stage 1: Compile-time filter
(LOG_MODULE_REGISTER level)"] + RT["Stage 2a: Runtime filter — slot 0 (aggregate)"] + BUF["Deferred message buffer (4KB MPSC)"] + THREAD["Central log processing thread"] + PERB["Stage 2b: Per-backend slot check"] + PRINTK_ENTRY["z_log_vprintk()
level = RAW_STRING (bypasses all filters)"] + end + + subgraph "Log Backends" + SHELL_UHK_LB["UhkShell log backend (slot N)"] + SHELL_RTT_LB["Shell RTT log backend (slot M)"] + PROXY_LB["UhkLog backend (slot K)"] + end + + subgraph "Shell Instances (each has own thread)" + SHELL_UHK["UhkShell thread"] + SHELL_RTT["Shell RTT thread"] + end + + subgraph "Output Sinks (shell_sinks_t)" + USB_BUF["USB log buffer"] + OLED["OLED console"] + STATUS["Macro status buffer"] + end + + subgraph "Physical Outputs" + UART_HW["UART hardware"] + RTT_HW["Segger RTT (J-Link)"] + end + + LOG --> CT + CT -->|"compiled in"| RT + CT -->|"compiled out → gone forever"| X1["∅"] + RT -->|"aggregate passes"| BUF + RT -->|"no backend wants it"| X2["∅"] + + PRINTK -->|"CONFIG_LOG_PRINTK=y (default)"| PRINTK_ENTRY + PRINTK_ENTRY -->|"always passes filters"| BUF + + BUF --> THREAD + THREAD --> PERB + PERB --> SHELL_UHK_LB + PERB --> SHELL_RTT_LB + PERB --> PROXY_LB + + SHELL_UHK_LB -->|"copy to private buf"| SHELL_UHK + SHELL_RTT_LB -->|"copy to private buf"| SHELL_RTT + + SHELL_UHK -->|"format & write"| UART_HW + SHELL_UHK -->|"transport sinks"| USB_BUF + SHELL_UHK -->|"transport sinks"| OLED + SHELL_UHK -->|"transport sinks"| STATUS + SHELL_RTT -->|"format & write"| RTT_HW + + PROXY_LB -->|"Stage 3: custom filter"| USB_BUF + PROXY_LB -->|"Stage 3: custom filter"| OLED + PROXY_LB -->|"Stage 3: custom filter"| STATUS + + LOGFN -->|"printk() internally"| PRINTK + LOGFN -->|"direct write"| OLED + LOGFN -->|"direct write"| STATUS + + style CT fill:#f66,color:#fff + style RT fill:#f96,color:#fff + style PERB fill:#fc6,color:#000 + style PROXY_LB fill:#6cf,color:#fff + style PRINTK_ENTRY fill:#9c6,color:#fff +``` + +**Note on `printk()`:** When `CONFIG_LOG_PRINTK=y` (the Zephyr default; this firmware does not override it), `printk()` creates a real log message with level `LOG_LEVEL_INTERNAL_RAW_STRING`. This special level **bypasses all runtime filters** — the message is delivered to every active backend unconditionally. This is why the `UhkLog` backend receives `printk()` messages. + +**Note on UHK `Log()`/`LogU()`/etc.:** These call `printk()` for UART output, so they also flow through the logging subsystem. But they also write directly to OLED and status buffer (bypassing logging entirely for those targets). + +## Shell Command Flow (Input → Execution → Output) + +```mermaid +sequenceDiagram + participant HW as UART Hardware + participant Transport as UHK UART Transport + participant Signal as k_poll_signal + participant Thread as UhkShell Thread + participant Core as Shell Core (state_collect) + participant Handler as Command Handler + + HW->>Transport: Byte received (async UART callback) + Transport->>Signal: raise(SHELL_SIGNAL_RXRDY) + Signal->>Thread: k_poll() wakes up + Thread->>Core: shell_process() + Core->>Transport: transport.read() — get bytes + Note over Core: Process VT100 escapes,
tab completion, history,
accumulate in cmd buffer + Core->>Core: Newline received → execute() + Core->>Handler: handler(shell, argc, argv) + Handler->>Thread: shell_print(shell, "output...") + Thread->>Transport: transport.write() — send bytes + Transport->>Transport: stripVt100() + outputToSinks() + Transport->>HW: Bytes sent via async UART +``` + +## Shell Log Message Flow (Two-Stage Delivery) + +Log messages reach shells through a **two-stage process**. This is deliberate — it decouples the central log thread from per-shell VT100 terminal management. + +```mermaid +sequenceDiagram + participant App as Application + participant LogCore as Log Processing Thread
(single, shared) + participant Filter as Runtime Filter Check + participant ShellLB as UhkShell's Log Backend
(process callback) + participant PrivBuf as UhkShell's Private
MPSC Buffer + participant ShellThread as UhkShell Thread
(dedicated) + participant Transport as UHK UART Transport + + App->>LogCore: LOG_INF("hello") → message in central buffer + LogCore->>LogCore: z_log_msg_claim() + LogCore->>Filter: msg_filter_check(backend, msg) + Filter-->>LogCore: pass/fail per backend slot + + LogCore->>ShellLB: log_backend_msg_process() + Note over ShellLB: Stage 1: copy, don't format yet + ShellLB->>PrivBuf: copy_to_pbuffer(msg) + ShellLB->>ShellThread: k_poll_signal_raise(SHELL_SIGNAL_LOG_MSG) + + Note over ShellThread: Stage 2: format and output + ShellThread->>ShellThread: k_poll() wakes on LOG_MSG signal + ShellThread->>ShellThread: Erase current command line (VT100) + ShellThread->>PrivBuf: claim message from private buffer + ShellThread->>ShellThread: log_output_msg_process() — format + ShellThread->>Transport: transport.write() — output formatted text + Transport->>Transport: stripVt100() + outputToSinks() + ShellThread->>ShellThread: Redraw prompt + partial command +``` + +This two-stage design means: +- The central log thread only does a fast memcpy, not formatting or VT100 manipulation +- Each shell thread handles its own terminal state (erasing/redrawing the command line around log output) +- Different shells can format independently without blocking each other + +## Per-Shell Log Filter Settings + +### The Filter Word + +When `CONFIG_LOG_RUNTIME_FILTERING=y`, each log source gets a 32-bit filter word in RAM, divided into 3-bit slots: + +``` +Bits: [29:27] [26:24] ... [8:6] [5:3] [2:0] +Slot: 9 8 ... 2 1 0 + | | | | | + Backend Backend Backend Backend AGGREGATE + 9 8 2 1 (max of all) +``` + +- **Slot 0 (aggregate):** Maximum level across all backend slots. Checked first — if the message level exceeds slot 0, the message is never allocated (saves CPU + memory). +- **Slots 1–N:** One per active backend. Each backend gets a unique slot ID assigned at `log_backend_enable()` time. + +### How `log enable` Works on a Specific Shell + +When you type `log enable dbg mymodule` on a shell: + +1. The command handler `cmd_log_self_enable()` in `log_cmds.c` receives `const struct shell *sh` — the shell instance you're typing on. +2. It accesses `sh->log_backend->backend` — the `struct log_backend` associated with **this** shell. +3. It calls `log_filter_set(sh->log_backend->backend, 0, source_id, LOG_LEVEL_DBG)`. +4. This writes `LOG_LEVEL_DBG` into this backend's 3-bit slot in the source's filter word. +5. Slot 0 (aggregate) is recalculated as `max(all backend slots)`. + +**Only this shell's slot changes.** The RTT shell and UhkLog backend are unaffected. + +To change a different backend's level, use `log backend enable dbg mymodule`. + +### What `log_filter_set(NULL, ...)` Does + +When backend is `NULL` (as used by UHK's `InitLogLevels()`), **all backend slots AND the aggregate** are set to the specified level. This is a bulk operation. + +### Full Filter Check Flow + +```mermaid +graph TD + MSG["LOG_INF() called for source 'Bt'"] + CT{"Compile-time:
INF ≤ LOG_MODULE_REGISTER level?"} + AGG{"Runtime slot 0:
INF ≤ aggregate?"} + ALLOC["Allocate message in central buffer"] + SLOT_UHK{"Slot N (UhkShell):
INF ≤ slot value?"} + SLOT_RTT{"Slot M (Shell RTT):
INF ≤ slot value?"} + SLOT_PROXY{"Slot K (UhkLog):
INF ≤ slot value?"} + DELIVER_UHK["→ Copy to UhkShell private buffer"] + DELIVER_RTT["→ Copy to RTT shell private buffer"] + DELIVER_PROXY["→ Call UhkLog.processLog()"] + SKIP["Skip this backend"] + DROP["Message never created"] + GONE["Compiled out of binary"] + + MSG --> CT + CT -->|yes| AGG + CT -->|no| GONE + AGG -->|yes| ALLOC + AGG -->|no| DROP + ALLOC --> SLOT_UHK + ALLOC --> SLOT_RTT + ALLOC --> SLOT_PROXY + SLOT_UHK -->|yes| DELIVER_UHK + SLOT_UHK -->|no| SKIP + SLOT_RTT -->|yes| DELIVER_RTT + SLOT_RTT -->|no| SKIP + SLOT_PROXY -->|yes| DELIVER_PROXY + SLOT_PROXY -->|no| SKIP + + style GONE fill:#f66,color:#fff + style DROP fill:#f96,color:#fff + style SKIP fill:#fc6,color:#000 +``` + +## The Three Filtering Stages (Detail) + +### Stage 1: Compile-Time Filtering + +Completely removes `LOG_*()` calls from the binary. Zero runtime cost. **Irreversible — no runtime API can bring these messages back.** + +Controlled by (highest precedence first): + +| Setting | Scope | Where | +|---------|-------|-------| +| `CONFIG_LOG_MAX_LEVEL` | Global ceiling | prj.conf (default: `LOG_LEVEL_INF`) | +| `CONFIG__LOG_LEVEL_*` | Per-Kconfig-module | prj.conf overlays | +| `LOG_MODULE_REGISTER(name, level)` | Per-source-file | C source code | +| `CONFIG_LOG_DEFAULT_LEVEL` | Default for unspecified modules | prj.conf (default: `LOG_LEVEL_INF`) | + +**UHK firmware examples:** + +```c +// charger.c — DBG and INF are compiled out, only WRN and ERR remain +LOG_MODULE_REGISTER(Battery, LOG_LEVEL_WRN); + +// bt_conn.c — DBG is compiled out +LOG_MODULE_REGISTER(Bt, LOG_LEVEL_INF); +``` + +```ini +# c2usb.conf — compiles DBG level into these modules +CONFIG_UDC_DRIVER_LOG_LEVEL_DBG=y +CONFIG_C2USB_HOGP_LOG_LEVEL_DBG=y +``` + +### Stage 2: Runtime Filtering (Per-Backend, Per-Source) + +Requires `CONFIG_LOG_RUNTIME_FILTERING=y` (enabled in this firmware). + +**Flow:** + +1. `LOG_INF("...")` called. Compile-time check passes. +2. Read slot 0 → if `INF > aggregate` → drop immediately, never allocate. +3. Slot 0 passes → message created, enqueued in central MPSC buffer. +4. Processing thread dequeues, iterates over backends. +5. For each backend: check that backend's slot → deliver or skip. + +**This is why a message can appear on one backend but not another.** + +**API:** + +```c +// Set filter for one backend + one source: +log_filter_set(backend, domain_id, source_id, level); + +// NULL backend = set ALL backend slots + aggregate (slot 0): +log_filter_set(NULL, 0, source_id, level); +``` + +**UHK usage** (`right/src/logger.c`): + +```c +void InitLogLevels() { + Shell_WaitUntilInitialized(); // critical — see Pitfall #1 + + setLevel("hogp", LOG_LEVEL_INF); // log_filter_set(NULL, ...) + setLevel("udc", LOG_LEVEL_WRN); + setLevel("udc_nrf", LOG_LEVEL_WRN); + setLevel("c2usb", LOG_LEVEL_WRN); +} +``` + +### Stage 3: Backend-Internal Filtering + +Custom logic inside a backend's `process` callback. Happens *after* the logging core already delivered the message. + +**UHK example** (`device/src/proxy_log_backend.c`): + +```c +static void processLog(..., union log_msg_generic *msg) { + shell_sinks_t sinks = ShellConfig_GetLogSinks(); + + if (WormCfg->devMode) { + // route c2usb warnings to status buffer in dev mode + uint8_t level = log_msg_get_level(&msg->log); + const char *sourceName = getLogSourceName(&msg->log); + if (level >= LOG_LEVEL_WRN && strcmp(sourceName, "c2usb") == 0) { + sinks.toStatusBuffer = true; + } + } + // only format if at least one output is active + if (sinks.toStatusBuffer || sinks.toUsbBuffer || sinks.toOled) { + log_output_msg_process(&logOutput, &msg->log, ...); + } +} +``` + +## UHK Firmware: Shell and Log Backends + +### Shell Instances + +| Shell | Transport | Registration | Purpose | +|-------|-----------|-------------|---------| +| **UhkShell** | Custom UHK UART transport | `SHELL_DEFINE` + `SYS_INIT` in `shell_uhk.c` | Primary interactive shell over UART, with VT100 stripping and output sink routing | +| **Shell RTT** | Segger RTT | Automatic via `CONFIG_SHELL_BACKEND_RTT=y` | Interactive shell over J-Link | + +**Disabled shell backends:** +- `CONFIG_SHELL_BACKEND_SERIAL=n` — replaced by UhkShell with custom transport +- `CONFIG_SHELL_BT_NUS=n` — BLE NUS shell disabled + +### Log Backends + +| Backend | Registration | Purpose | +|---------|-------------|---------| +| UhkShell's log backend | Automatic via `SHELL_DEFINE` | Log output to UART (+ sinks via transport) | +| Shell RTT's log backend | Automatic via `CONFIG_SHELL_BACKEND_RTT` | Log output to J-Link | +| **UhkLog** | `LOG_BACKEND_DEFINE()` in `proxy_log_backend.c` | Routes to USB buffer, OLED, status buffer via sinks | + +Each gets an auto-assigned slot ID and independent per-source filter levels. + +### The UHK UART Transport (`shell_transport_uhk.c`) + +The UhkShell uses a custom transport instead of Zephyr's standard `shell_uart.c`. Key differences: + +- **Async UART** with 4 RX buffers of 16 bytes each +- **VT100 stripping**: All output passes through `stripVt100()` before routing to sinks, removing escape sequences that would garble non-terminal outputs +- **Output sink routing**: Every `write()` call routes the VT100-stripped output to configured sinks (USB buffer, OLED, status buffer) in addition to sending raw bytes to the physical UART +- **Uninit/Reinit API**: `ShellUartTransport_Uninit()` / `ShellUartTransport_Reinit()` for UART pin rerouting during boot + +### The Sinks System (`device/src/shell/sinks.c`) + +The sinks system provides a unified routing configuration for both shell output and log output. It controls three destinations: + +| Sink | Target | When Active | +|------|--------|-------------| +| `toUsbBuffer` | `UsbLogBuffer_Print()` — 2KB circular buffer for USB retrieval | `WormCfg->UsbLogEnabled` | +| `toOled` | `Oled_LogConstant()` / `Oled_Log()` — OLED console widget | `WormCfg->UsbLogEnabled` | +| `toStatusBuffer` | `Macros_SanitizedPut()` — macro status buffer | `ShellConfig_IsInPanicMode` | + +**Mutual exclusion**: A `useShellSinks` flag (currently `false`) controls whether sinks are fed from shell output or log output: + +```c +shell_sinks_t ShellConfig_GetShellSinks(void) { + return useShellSinks ? activeConfig() : emptyConfig(); +} +shell_sinks_t ShellConfig_GetLogSinks(void) { + return useShellSinks ? emptyConfig() : activeConfig(); +} +``` + +- **`useShellSinks = false` (current)**: Log messages (via UhkLog backend) go to sinks; shell command output goes only to UART. +- **`useShellSinks = true`**: Shell command output goes to sinks; log messages go only to their shell backends (UART/RTT). + +This prevents duplicate output — without mutual exclusion, a `printk()` would appear on sinks both via UhkLog *and* via the UhkShell transport (since `printk()` flows through the shell's log backend and gets written via the transport). + +**Panic mode**: `ShellConfig_ActivatePanicMode()` forces `toStatusBuffer = true`, persists the status buffer across reboots via the state wormhole, and prints a panic header with trace. + +### OLED Console Widget (`console_widget.c`) + +The OLED console is a circular line buffer rendered bottom-to-top (newest at bottom) on the debug screen. + +**Newline handling**: Text is processed character-by-character: +- Regular characters append to the current line at the current column +- `\n` advances to a new line only if the current line is non-empty (empty lines are suppressed) +- `\r` is skipped +- Lines that exceed `CONSOLE_BUFFER_LINE_LENGTH` are truncated +- Text without a trailing `\n` stays on the current line — the next call appends to it + +**Prompt abbreviation**: The shell prompt `uhk80:right$` is replaced with just `$` to save screen space. + +### Shell Command Execution API + +Shell commands can be executed programmatically via `Shell_Execute()` (`shell_uhk.c`): + +```c +void Shell_Execute(const char *cmd, const char *source); +``` + +Entry points: +- **USB**: `UsbCommand_ExecShellCommand()` → `Shell_Execute(cmd, "usb")` +- **Macros**: `shell` macro command → `Shell_Execute(cmd, "macro")` + +The function retrieves the UhkShell instance, sets a default terminal width of 80 if unset (prevents division-by-zero in Zephyr's shell formatting), and calls `shell_execute_cmd()`. + +## UHK Firmware Relevant Configuration + +```ini +# nrf_shared.conf +CONFIG_LOG=y +CONFIG_LOG_MODE_DEFERRED=y # Background thread processes logs +CONFIG_LOG_BUFFER_SIZE=4096 # Central circular buffer for deferred messages +CONFIG_LOG_RUNTIME_FILTERING=y # Per-backend per-source runtime filters +CONFIG_LOG_CMDS=y # Shell "log" commands available +CONFIG_LOG_BACKEND_SHOW_COLOR=y # ANSI color codes +# CONFIG_LOG_PRINTK defaults to y # printk() routed through logging subsystem + +CONFIG_SHELL=y +CONFIG_SHELL_BACKENDS=y +CONFIG_SHELL_BACKEND_SERIAL=n # Disabled — replaced by UhkShell custom transport +CONFIG_SHELL_BT_NUS=n # BLE NUS shell disabled + +# prj.conf (debug build) +CONFIG_SHELL_BACKEND_RTT=y # RTT shell +``` + +## File Organization + +``` +device/src/ +├── shell.h # shell_t struct (keyLog, statLog, etc.) +├── proxy_log_backend.c # UhkLog log backend — routes to sinks +└── shell/ + ├── shell_uhk.c # UhkShell instance, Shell_WaitUntilInitialized, Shell_Execute + ├── shell_uhk.h + ├── shell_transport_uhk.c # Custom UART transport with VT100 stripping + sink routing + ├── shell_transport_uhk.h + ├── shell_backend_usb.c # ShellBackend_ListBackends(), ShellBackend_Exec() utilities + ├── shell_backend_usb.h + ├── sinks.c # Output sink configuration and routing + └── sinks.h +``` + +## UHK Shell Reinitialization Sequence (UHK80 Right only) + +The UHK80 Right has dynamic UART pin routing — the same UART peripherals serve different functions depending on `Settings_UartDebugMode`. This requires uninitializing and reinitializing the shell during boot: + +```mermaid +sequenceDiagram + participant Boot as Boot (main.c) + participant Transport as UHK UART Transport + participant Shell as UhkShell + participant PW as PinWiring + participant UART as UART0 HW + + Note over Boot: UhkShell auto-started at POST_KERNEL with default pins + Boot->>Transport: ShellUartTransport_Uninit() + Transport->>UART: uart_rx_disable() + Transport->>Transport: uartEnabled = false + Boot->>PW: PinWiring_Suspend() + PW->>UART: pm_device_action_run(SUSPEND) + Boot->>PW: PinWiring_SelectRouting() + Note over PW: Pick config based on Settings_UartDebugMode + Boot->>PW: PinWiring_ConfigureRouting() + Note over PW: pinctrl_update_states() — remap physical pins + Boot->>PW: PinWiring_Resume() + PW->>UART: pm_device_action_run(RESUME) + Boot->>Transport: ShellUartTransport_Reinit() + Transport->>UART: uart_rx_disable() (defensive) + Transport->>UART: uart_callback_set() + Transport->>UART: uart_rx_enable() + Transport->>Transport: uartEnabled = true + Boot->>Shell: Shell_WaitUntilInitialized() + Note over Boot: Shell ready, log filters can now be set safely +``` + +### Known Issue: UART Shell Input Broken After Cold Reboot + +**Symptom:** After a cold reboot (e.g., `NVIC_SystemReset` or watchdog reset) *without* disconnecting power, the UART shell shows output but does not accept input. A full power cycle fixes it. + +**Likely cause:** On nRF chips, a soft reset does **not** reset UART peripheral registers. The UART hardware retains state from before the reset: + +1. The UART peripheral's RX EVENTS may still be set +2. The async UART driver's internal state machine thinks RX is already active +3. When `uart_rx_enable()` is called during reinit, the driver returns `-EBUSY` because it thinks an RX transfer is already in progress +4. The shell init may silently ignore this error, leaving RX permanently disabled +5. TX works because it doesn't have this stateful issue — each `write()` is independent + +**Mitigation:** `ShellUartTransport_Reinit()` now calls `uart_rx_disable()` defensively before re-enabling RX. More aggressive approaches (forcing the UART peripheral into a known state at register level) may be needed. + +## Pitfalls + +### Pitfall 1: Shell Init Overwrites Runtime Filters + +When `shell_start()` enables the shell's log backend via `log_backend_enable()`, it sets the filter for **every source** to the shell's `init_log_level`. If you called `log_filter_set()` before the shell finished starting, your settings get overwritten. + +**UHK workaround** (`device/src/shell/shell_uhk.c`): + +```c +void Shell_WaitUntilInitialized(void) { + const struct shell *sh = ShellUhk_GetShellPtr(); + if (sh) { + // if we set levels before shell is ready, the shell will + // mercilessly overwrite them + while (!shell_ready(sh)) { + k_msleep(10); + } + } +} +``` + +**Note:** This only waits for the UhkShell. If the RTT shell initializes later, it could still overwrite filters for its own slot. + +### Pitfall 2: Message Reaches One Backend But Not Another + +Per-backend slots are independent. If UhkShell's slot for "Bt" is `LOG_LEVEL_INF` but UhkLog's slot is `LOG_LEVEL_ERR`, then `LOG_INF()` from the Bt module appears on UART but not in the proxy. + +Using `log_filter_set(NULL, ...)` sets **all** backend slots uniformly. But subsequent `log enable` shell commands only change one backend's slot. + +**Diagnosis:** Use `log status` on the shell to see per-module levels. Compare across different shell backends. + +### Pitfall 3: Compile-Time Level is Too Restrictive + +If a module is registered with `LOG_MODULE_REGISTER(Battery, LOG_LEVEL_WRN)`, then `LOG_INF()` calls in that module are compiled out. No amount of `log enable inf Battery` will bring them back — you must change the source code and rebuild. + +`log status` shows both the runtime filter and the compiled-in ceiling, so you can diagnose this. + +### Pitfall 4: Aggregate (Slot 0) Gate + +If no backend wants `LOG_LEVEL_DBG` for a source, the aggregate (slot 0) won't include DBG. The message is dropped before allocation and no backend ever sees it. You must raise at least one backend's slot to DBG to get the aggregate to include it. + +### Pitfall 5: `printk()` Bypasses All Filters (but NOT the logging subsystem) + +With `CONFIG_LOG_PRINTK=y` (the default), `printk()` creates a log message with level `LOG_LEVEL_INTERNAL_RAW_STRING`, which **bypasses all runtime filters**. The message reaches every active backend unconditionally. + +This means `printk()` output appears on UhkShell (UART), RTT shell, AND the UhkLog backend. It cannot be silenced via `log disable` or runtime filter settings. + +UHK's `Log()`/`LogU()` functions use `printk()` internally for UART output, so they also go through this path. + +### Pitfall 6: Shell's Private Buffer Can Fill Up + +Each shell has a small private MPSC buffer for log messages. If the shell thread can't drain it fast enough (e.g., the transport is slow, or the thread is preempted), the central log thread's `copy_to_pbuffer()` fails and the message is **dropped** for that shell only. Other backends are unaffected. The shell reports drops via its `dropped()` callback. + +### Pitfall 7: Duplicate Output via Sinks + +Because `printk()` messages flow through both the UhkLog backend and the UhkShell's log backend (which writes via the transport), enabling sinks on both paths would cause duplicate output. The `useShellSinks` toggle in `sinks.c` prevents this by routing sinks to exactly one path at a time. + +## References + +### Zephyr Official Documentation + +- [Zephyr Logging Subsystem](https://docs.zephyrproject.org/latest/services/logging/index.html) — official reference for logging architecture, filtering, backends, modes +- [Zephyr Shell Subsystem](https://docs.zephyrproject.org/latest/services/shell/index.html) — official reference for shell architecture, transports, commands +- [CONFIG_LOG_PRINTK](https://docs.zephyrproject.org/1.13.0/reference/kconfig/CONFIG_LOG_PRINTK.html) — Kconfig reference for printk-to-logging redirect (default `y` since Zephyr 3.3) + +### Zephyr Source Code + +- [log_core.c](https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/logging/log_core.c) — log processing thread, message dispatch, filter checks +- [log_cmds.c](https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/logging/log_cmds.c) — shell `log enable/disable/status` command implementation + +### Zephyr GitHub Discussions & Issues + +- [shell_init overrides log filters set by modules (#55703)](https://github.com/zephyrproject-rtos/zephyr/discussions/55703) — the exact pitfall #1 described above +- [Filtering of logs to different backends (#68322)](https://github.com/zephyrproject-rtos/zephyr/discussions/68322) — per-backend filtering discussion +- [Runtime Filtering of Log Levels Not Working Properly (#72818)](https://github.com/zephyrproject-rtos/zephyr/issues/72818) — runtime filter issues +- [Compiling debug logs, but set log level to info by default (#57957)](https://github.com/zephyrproject-rtos/zephyr/discussions/57957) — compile-time vs runtime level separation +- [Incorrect init sequence when log thread has lower priority (#87276)](https://github.com/zephyrproject-rtos/zephyr/issues/87276) — log thread priority and init ordering + +### Nordic DevZone — UART Reset Issues + +- [UART and UARTE state after reset](https://devzone.nordicsemi.com/f/nordic-q-a/62019/uart-and-uarte-state-after-reset) — UART peripheral state not reset after soft reset +- [UART RX not working after power cycle](https://devzone.nordicsemi.com/f/nordic-q-a/118351/uart-rx-not-working-after-power-cycle) — RX issues after reset +- [Serial RX DATA event not firing after hard reset](https://devzone.nordicsemi.com/f/nordic-q-a/48324/serial-rx-data-event-not-firing-after-hard-reset) — stale RX FIFO bytes after reset +- [UART Overrun Error after Reset](https://devzone.nordicsemi.com/f/nordic-q-a/18481/uart-overrun-error-after-reset) — overrun errors from stale peripheral state +- [nRF52832 Softreset](https://devzone.nordicsemi.com/f/nordic-q-a/60653/nrf52832-softreset) — general soft reset peripheral behavior + +### Blog Posts + +- [Debugging Zephyr for Beginners: printk() and the Logging Subsystem (Golioth)](https://blog.golioth.io/debugging-zephyr-for-beginners-printk-and-the-logging-subsystem/) — beginner-friendly overview of printk vs LOG_* and CONFIG_LOG_PRINTK +- [Useful Zephyr Shells for IoT Development (Golioth)](https://blog.golioth.io/useful-zephyr-shells-for-iot-development/) — practical shell usage guide +- [Practical Zephyr - Kconfig (Memfault Interrupt)](https://interrupt.memfault.com/blog/practical_zephyr_kconfig) — Kconfig logging configuration examples diff --git a/doc-dev/other/troubleshooting_c2usb.md b/doc-dev/other/troubleshooting_c2usb.md index 3de7edf84..cb30cf722 100644 --- a/doc-dev/other/troubleshooting_c2usb.md +++ b/doc-dev/other/troubleshooting_c2usb.md @@ -24,12 +24,12 @@ You can see the logs in real time: Create this macro and bind it somewhere convenient: ``` -zephyr uhk snaplog +zephyr uhk log snapshot ``` -Reproduce the issue. +Reproduce the issue. -Run the `snaplog` macro. This will export the usb log buffer into the persistent status buffer. +Run the `log snapshot` macro. This will export the usb log buffer into the persistent status buffer. Bring usb back to life. If need be, restart uhk using its reset button, but do not powercycle it. diff --git a/right/src/logger.c b/right/src/logger.c index 3f6f2196f..d4dec4037 100644 --- a/right/src/logger.c +++ b/right/src/logger.c @@ -10,7 +10,7 @@ #ifdef __ZEPHYR__ - #include "shell.h" + #include "shell/shell_uhk.h" #include "nus_client.h" #include "nus_server.h" #include "messenger.h" diff --git a/right/src/macros/commands.c b/right/src/macros/commands.c index d4b4a0622..8e79f457b 100644 --- a/right/src/macros/commands.c +++ b/right/src/macros/commands.c @@ -45,7 +45,7 @@ #ifdef __ZEPHYR__ #include "connections.h" #include "bt_pair.h" -#include "shell.h" +#include "shell/shell_uhk.h" #include "host_connection.h" #else #include "segment_display.h" diff --git a/right/src/power_mode.c b/right/src/power_mode.c index d41ce37cc..cfc5ac43e 100644 --- a/right/src/power_mode.c +++ b/right/src/power_mode.c @@ -14,7 +14,6 @@ #include "keyboard/charger.h" #include "keyboard/leds.h" #include "state_sync.h" - #include "proxy_log_backend.h" #else #include "slave_drivers/is31fl3xxx_driver.h" #include "usb_composite_device.h" @@ -257,7 +256,6 @@ void PowerMode_RestartedTo(power_mode_t mode) { KeyBacklightBrightness = 0; lastDeepPowerMode = mode; - InitProxyLogBackend(); InitLeds_Min(); InitKeyScanner_Min(); InitCharger_Min(); diff --git a/right/src/trace.c b/right/src/trace.c index 6b5d8af1b..7076cc8db 100644 --- a/right/src/trace.c +++ b/right/src/trace.c @@ -8,9 +8,9 @@ #include "device.h" #ifdef __ZEPHYR__ -#include "proxy_log_backend.h" +#include "shell/sinks.h" #else -#define ProxyLog_IsInPanicMode false +#define ShellConfig_IsInPanicMode false #endif bool Trace_Enabled = true; @@ -34,7 +34,7 @@ void Trace_Print(log_target_t additionalLogTargets, const char* reason) { device_id_t targetDeviceId = DEVICE_ID; log_target_t targetInterface = 0; - if (ProxyLog_IsInPanicMode) { + if (ShellConfig_IsInPanicMode) { targetInterface = LogTarget_Uart; } else { targetInterface = LogTarget_Uart | additionalLogTargets; diff --git a/right/src/usb_commands/usb_command_exec_shell_command.c b/right/src/usb_commands/usb_command_exec_shell_command.c index dc277f2b0..92b4f4aa1 100644 --- a/right/src/usb_commands/usb_command_exec_shell_command.c +++ b/right/src/usb_commands/usb_command_exec_shell_command.c @@ -3,7 +3,7 @@ #define USB_SHELL_COMMAND_MAX_LEN (USB_GENERIC_HID_OUT_BUFFER_LENGTH - 1) -#include "shell.h" +#include "shell/shell_uhk.h" void UsbCommand_ExecShellCommand(const uint8_t *GenericHidOutBuffer, uint8_t *GenericHidInBuffer) {