From 4d934ce47b7f790bd4dbb7bdeaaa6d284ad330b2 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 18:21:02 +0200 Subject: [PATCH 01/24] Bridge: add link statistics. Frame/ack/resend counters, RX stop reasons, and ack latency histograms (sender: uart_tx -> ack parsed; receiver: frame parsed -> ack handed to uart_tx). Printed by 'uhk uartStats' and included in the 'uhk recover' dump. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 116 ++++++++++++++++++++++++++++-- device/src/keyboard/uart_bridge.h | 3 + device/src/keyboard/uart_link.c | 14 ++++ device/src/keyboard/uart_link.h | 8 +++ device/src/shell/shell_commands.c | 14 ++++ right/src/macros/debug_commands.c | 4 ++ 6 files changed, 155 insertions(+), 4 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 8fd9f44cd..e1a155413 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -50,6 +50,10 @@ typedef struct { uint16_t invalidMessagesCounter; uint8_t resendTries; + // Cycle stamps for the latency stats below. + uint32_t sentCyc; // last uart_tx of a data frame + uint32_t ackReqCyc; // last valid frame parsed (ack requested) + uint8_t* rxBuffer; uint8_t txBuffer[UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH]; @@ -71,6 +75,53 @@ uart_state_t bridgeState = {0}; static bool bridgeSuspended = false; static bool bridgeTxSlotHeld = false; +// Diagnostics, cumulative since boot. Printed by UartBridge_DumpStats. +#define LATENCY_BUCKETS 5 + +typedef struct { + uint32_t maxUs; + uint32_t sumUs; + uint32_t count; + uint16_t hist[LATENCY_BUCKETS]; // <1ms, <4ms, <16ms, <64ms, >=64ms +} latency_stats_t; + +typedef struct { + uint32_t framesSent; + uint32_t framesReceived; + uint16_t ackWhileIdle; // ack arrived while we weren't waiting for one + uint16_t nackWhileIdle; + uint16_t nackReceived; + uint16_t resendTimeout; + uint16_t resendNack; + uint16_t giveUps; + uint16_t txSendFail; // uart_tx returned an error + uint16_t unexpectedBytes; + latency_stats_t ackLoop; // sender: uart_tx of a frame -> its ack parsed + latency_stats_t ackTurn; // receiver: frame parsed -> ack handed to uart_tx +} uart_bridge_stats_t; + +static uart_bridge_stats_t stats = {0}; + +static void recordLatency(latency_stats_t* s, uint32_t startCyc) { + uint32_t us = k_cyc_to_us_floor32(k_cycle_get_32() - startCyc); + uint8_t bucket; + if (us < 1000) { + bucket = 0; + } else if (us < 4000) { + bucket = 1; + } else if (us < 16000) { + bucket = 2; + } else if (us < 64000) { + bucket = 3; + } else { + bucket = 4; + } + s->hist[bucket]++; + s->count++; + s->sumUs += us; + s->maxUs = MAX(s->maxUs, us); +} + /* UART message format: * [START_BYTE,crc16,escaped(messengerPacket), ENDBYTE] * crcMessage = 4 bytes = CRC16 in format [ESCAPE_BYTE,byte1,ESCAPE_BYTE,byte2] @@ -136,15 +187,21 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ switch (messageKind) { case UartControl_Ack: if (uartState->txState == UartTxState_WaitingForAck) { + recordLatency(&stats.ackLoop, uartState->sentCyc); uartState->resendTries = 0; uartState->txState = UartTxState_Idle; k_sem_give(&uartState->txBufferBusy); + } else { + stats.ackWhileIdle++; } break; case UartControl_Nack: if (uartState->txState == UartTxState_WaitingForAck) { + stats.nackReceived++; uartState->txState = UartTxState_Resend; wakeControlThread(uartState); + } else { + stats.nackWhileIdle++; } break; case UartControl_Ping: @@ -153,6 +210,8 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ case UartControl_ValidMessage: { uartState->lastPingTime = k_uptime_get(); + stats.framesReceived++; + uartState->ackReqCyc = k_cycle_get_32(); setRxState(uartState, UartRxState_Ack); // message @@ -184,6 +243,7 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ } break; case UartControl_Unexpected: + stats.unexpectedBytes++; #if UART_LOWPOWER // Out-of-frame garbage is expected here: enabling RX mid-byte after a GPIO wake // yields a partial byte or the tail of the wake byte. The parser resyncs on the @@ -229,8 +289,11 @@ int UartBridge_SendMessage(message_t* msg) { UartParser_AppendEscapedTxBytes(&uartState->parser, msg->data, msg->len); UartParser_FinalizeMessage(&uartState->parser); + stats.framesSent++; + uartState->sentCyc = k_cycle_get_32(); err = UartLink_Send(&uartState->core, uartState->parser.txBuffer, uartState->parser.txPosition); if (err != 0) { + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } @@ -241,11 +304,16 @@ int UartBridge_SendMessage(message_t* msg) { return err; } -static void sendControl(uart_state_t *uartState, uint8_t byte) { +static void sendControl(uart_state_t *uartState, uint8_t byte, bool isAck) { UartLink_LockBusy(&uartState->core); + if (isAck) { + // Measured once we hold the TX slot: includes waiting out our own in-flight frame. + recordLatency(&stats.ackTurn, uartState->ackReqCyc); + } int err = UartLink_Send(&uartState->core, &byte, 1); if (err != 0) { // No transfer started -> no TX_DONE -> return the slot ourselves. + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } } @@ -256,7 +324,13 @@ static void sendControl(uart_state_t *uartState, uint8_t byte) { // k_sleep - it runs on the control thread, where blocking makes us blind to wake edges, // acks and pings, which used to cascade into a disconnect + BLE-fallback feedback loop. static void resend(uart_state_t *uartState, bool wakePeer) { + if (wakePeer) { + stats.resendTimeout++; + } else { + stats.resendNack++; + } if (uartState->resendTries++ > UART_RESEND_COUNT) { + stats.giveUps++; LogU("Repeatedly failed to send a message! "); for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { LogU("%i ", uartState->parser.txBuffer[i]); @@ -273,9 +347,11 @@ static void resend(uart_state_t *uartState, bool wakePeer) { UartLink_SendWakeByte(&uartState->core); } UartLink_LockBusy(&uartState->core); + uartState->sentCyc = k_cycle_get_32(); int err = UartLink_Send(&uartState->core, uartState->parser.txBuffer, uartState->parser.txPosition); if (err != 0) { // No transfer started -> no TX_DONE -> return the slot ourselves. + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } uartState->lastMessageSentTime = k_uptime_get(); @@ -333,7 +409,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (currentTime >= lastPingSentTime + UART_BRIDGE_PING_INTERVAL) { UartLink_WakeRx(&uartState->core); UartLink_SendWakeByte(&uartState->core); - sendControl(uartState, UartControlByte_Ping); + sendControl(uartState, UartControlByte_Ping, false); lastPingSentTime = currentTime; } @@ -342,11 +418,11 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (Connections_IsReady(uartState->connectionId)) { switch (uartState->rxState) { case UartRxState_Ack: - sendControl(uartState, UartControlByte_Ack); + sendControl(uartState, UartControlByte_Ack, true); uartState->rxState = UartRxState_Idle; break; case UartRxState_Nack: - sendControl(uartState, UartControlByte_Nack); + sendControl(uartState, UartControlByte_Nack, false); uartState->rxState = UartRxState_Idle; break; case UartRxState_Idle: @@ -515,3 +591,35 @@ void UartBridge_Resume(void) { wakeControlThread(uartState); } + +static void dumpLatency(const char* label, const latency_stats_t* s) { + uint32_t meanUs = s->count == 0 ? 0 : s->sumUs / s->count; + LogU(" %s: n=%u mean=%uus max=%uus\n", label, (unsigned)s->count, (unsigned)meanUs, (unsigned)s->maxUs); + LogU(" hist <1/<4/<16/<64/>=64ms: %u/%u/%u/%u/%u\n", + (unsigned)s->hist[0], (unsigned)s->hist[1], (unsigned)s->hist[2], (unsigned)s->hist[3], (unsigned)s->hist[4]); +} + +void UartBridge_DumpStats(void) { + uart_state_t *uartState = &bridgeState; + uart_link_t *core = &uartState->core; + if (core->device == NULL) { + LogU("Uart bridge: no bridge uart on this routing\n"); + return; + } + LogU("Uart bridge stats (t=%u ms): enabled=%d txState=%d rxState=%d resendTries=%u\n", + (unsigned)Timer_GetCurrentTime(), (int)core->enabled, (int)uartState->txState, (int)uartState->rxState, + (unsigned)uartState->resendTries); + LogU(" frames: sent=%u received=%u crcInvalid=%u unexpectedBytes=%u\n", + (unsigned)stats.framesSent, (unsigned)stats.framesReceived, (unsigned)uartState->invalidMessagesCounter, + (unsigned)stats.unexpectedBytes); + LogU(" acks: whileIdle=%u nack=%u nackWhileIdle=%u\n", + (unsigned)stats.ackWhileIdle, (unsigned)stats.nackReceived, (unsigned)stats.nackWhileIdle); + LogU(" resends: timeout=%u nack=%u giveUps=%u txSendFail=%u txAborted=%u\n", + (unsigned)stats.resendTimeout, (unsigned)stats.resendNack, (unsigned)stats.giveUps, + (unsigned)stats.txSendFail, (unsigned)core->txAbortedCount); + LogU(" rx stopped: overrun=%u framing=%u break=%u other=%u disabled=%u\n", + (unsigned)core->rxStoppedOverrun, (unsigned)core->rxStoppedFraming, (unsigned)core->rxStoppedBreak, + (unsigned)core->rxStoppedOther, (unsigned)core->rxDisabledCount); + dumpLatency("ackLoop (send->ack)", &stats.ackLoop); + dumpLatency("ackTurn (rx->ack tx)", &stats.ackTurn); +} diff --git a/device/src/keyboard/uart_bridge.h b/device/src/keyboard/uart_bridge.h index 55aa6037a..a88eea70a 100644 --- a/device/src/keyboard/uart_bridge.h +++ b/device/src/keyboard/uart_bridge.h @@ -28,4 +28,7 @@ void UartBridge_Suspend(void); void UartBridge_Resume(void); + // Print bridge link diagnostics (frame/ack/resend counters, ack latencies) to the uart log. + void UartBridge_DumpStats(void); + #endif // __UART_H__ diff --git a/device/src/keyboard/uart_link.c b/device/src/keyboard/uart_link.c index fa0e0d29e..e9fa11f56 100644 --- a/device/src/keyboard/uart_link.c +++ b/device/src/keyboard/uart_link.c @@ -26,6 +26,7 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void case UART_TX_ABORTED: // TODO: is this needed? // uart_tx(uartState->device, uartState->txBuffer, uartState->txPosition, UART_TIMEOUT); + uartState->txAbortedCount++; LogU("Tx aborted. Please report this!\n"); break; @@ -57,6 +58,7 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void case UART_RX_DISABLED: uartState->enabled = false; + uartState->rxDisabledCount++; // Every RX teardown lands here, including driver-initiated ones (framing/break // errors are routine when RX is enabled mid-byte after a GPIO wake). Let the owner // re-arm RX if it wants it up - otherwise the link stays deaf. @@ -69,6 +71,18 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void // reason: 1=overrun 2=parity 4=framing 8=break (uart.h uart_rx_stop_reason) BridgeDbg("BRIDGE RX_STOPPED reason %d\n", evt->data.rx_stop.reason); uartState->enabled = false; + { + uint8_t reason = evt->data.rx_stop.reason; + if (reason & UART_ERROR_OVERRUN) { + uartState->rxStoppedOverrun++; + } else if (reason & UART_ERROR_FRAMING) { + uartState->rxStoppedFraming++; + } else if (reason & UART_BREAK) { + uartState->rxStoppedBreak++; + } else { + uartState->rxStoppedOther++; + } + } break; } } diff --git a/device/src/keyboard/uart_link.h b/device/src/keyboard/uart_link.h index 7abff8b51..63e6cda7d 100644 --- a/device/src/keyboard/uart_link.h +++ b/device/src/keyboard/uart_link.h @@ -60,6 +60,14 @@ struct k_sem txControlBusy; bool enabled; + // Diagnostics, printed by UartBridge_DumpStats. + uint16_t rxStoppedOverrun; + uint16_t rxStoppedFraming; + uint16_t rxStoppedBreak; + uint16_t rxStoppedOther; + uint16_t rxDisabledCount; + uint16_t txAbortedCount; + // Low-power (UART_LOWPOWER) state struct gpio_dt_spec rxWakePin; // RXD as a GPIO; .port == NULL disables LP struct gpio_callback rxWakeCb; diff --git a/device/src/shell/shell_commands.c b/device/src/shell/shell_commands.c index abde6803f..e371d7dc2 100644 --- a/device/src/shell/shell_commands.c +++ b/device/src/shell/shell_commands.c @@ -24,6 +24,9 @@ #include "stubs.h" #include "slave_drivers/kboot_driver.h" #include "pin_wiring.h" +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT +#include "keyboard/uart_bridge.h" +#endif #include "slot.h" #include "i2c_addresses.h" #include "test_suite/test_suite.h" @@ -523,6 +526,14 @@ static int cmd_uhk_recover(const struct shell *shell, size_t argc, char *argv[]) return 0; } +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT +static int cmd_uhk_uartStats(const struct shell *shell, size_t argc, char *argv[]) +{ + UartBridge_DumpStats(); + return 0; +} +#endif + static int cmd_uhk_jitterTest(const struct shell *shell, size_t argc, char *argv[]) { if (argc == 1) { @@ -597,6 +608,9 @@ void InitShellCommands(void) SHELL_CMD_ARG(testSuite, NULL, "run test suite [module] [test]", cmd_uhk_testSuite, 1, 2), SHELL_CMD_ARG(jitterTest, NULL, "get/set mouse jitter test mode", cmd_uhk_jitterTest, 1, 1), SHELL_CMD_ARG(listActiveKeys, NULL, "list currently pressed keys", cmd_uhk_listActiveKeys, 1, 0), +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT + SHELL_CMD_ARG(uartStats, NULL, "print bridge uart link statistics", cmd_uhk_uartStats, 1, 0), +#endif SHELL_CMD_ARG(printStatus, NULL, "print the macro status buffer", cmd_uhk_printStatus, 1, 0), SHELL_CMD_ARG(recover, NULL, "dump diagnostics into the status buffer and reboot", cmd_uhk_recover, 1, 0), SHELL_CMD_ARG(reportEventVector, NULL, "decode an EventVector mask value", cmd_uhk_reportEventVector, 2, 0), diff --git a/right/src/macros/debug_commands.c b/right/src/macros/debug_commands.c index 9646c28c9..43cb9b4f2 100644 --- a/right/src/macros/debug_commands.c +++ b/right/src/macros/debug_commands.c @@ -23,6 +23,7 @@ #include "keyboard/battery_manager.h" #include "keyboard/battery_percent_calculator.h" #include "state_sync.h" +#include "keyboard/uart_bridge.h" #endif macro_result_t Macros_ProcessStatsLayerStackCommand() @@ -153,6 +154,9 @@ void Macros_RecoverDiagnostics(void) Macros_ProcessClearStatusCommand(true); c2usb_diag_dump(); Hid_DumpTransportState(); +#if DEVICE_IS_KEYBOARD && defined(__ZEPHYR__) + UartBridge_DumpStats(); +#endif Trace_Print(LogTarget_Uart | LogTarget_ErrorBuffer, "Diagnostics reboot."); StateWormhole.persistStatusBuffer = true; Reboot(false); From 5d560fd2b293aff07d6c50867911cea7259f9b75 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 18:21:22 +0200 Subject: [PATCH 02/24] Bridge: don't tear RX down on out-of-frame bytes. After any RX teardown, bridgeOnRxDisabled resyncs the parser while the peer's frame may still be streaming in; the rest of it arrived as 'unexpected' bytes, each of which reset RX again (10ms deaf, mid-frame re-enable) until the frame ended. Let the parser resync on the next Start byte instead, as the low-power build already did. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index e1a155413..02be9b89b 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -243,16 +243,14 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ } break; case UartControl_Unexpected: + // Out-of-frame garbage: a byte received while the parser is between frames. It is + // routine after any RX teardown - bridgeOnRxDisabled resyncs the parser while the + // peer's frame may still be streaming in, so its remaining bytes land here. The + // parser resyncs itself on the next Start byte. Tearing RX down here instead + // (the old UartLink_Reset) made every such byte another teardown, another mid-frame + // re-enable, and so on until the frame ended - one lost frame per hiccup. stats.unexpectedBytes++; -#if UART_LOWPOWER - // Out-of-frame garbage is expected here: enabling RX mid-byte after a GPIO wake - // yields a partial byte or the tail of the wake byte. The parser resyncs on the - // next Start byte, whereas resetting RX (10ms of deafness, wake sense unarmed) - // exactly when the real frame is inbound turns one garbled byte into a resend storm. BridgeDbg("BRIDGE RX unexpected byte\n"); -#else - UartLink_Reset(&uartState->core); -#endif break; } } From cbe2dc8e06767c2dc2d63bdce10810f4c1de7f44 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 18:21:22 +0200 Subject: [PATCH 03/24] Messenger: drop duplicate frames. Restore the watermark check removed in 8d055e544: a frame whose ack got lost is resent with the same watermark and must not be applied twice (left key states carry cursor deltas). rxIdxValid exempts the first frame after a local watermark reset. Co-Authored-By: Claude Fable 5.1 --- device/src/connections.c | 1 + device/src/connections.h | 1 + device/src/messenger.c | 13 ++++++++++++- 3 files changed, 14 insertions(+), 1 deletion(-) diff --git a/device/src/connections.c b/device/src/connections.c index 36a2544dd..83061acaf 100644 --- a/device/src/connections.c +++ b/device/src/connections.c @@ -143,6 +143,7 @@ void Connections_ResetWatermarks(connection_id_t connectionId) { Connections[connectionId].watermarks.txIdx = 0; Connections[connectionId].watermarks.rxIdx = 255; + Connections[connectionId].watermarks.rxIdxValid = false; } void Connections_ReportState(connection_id_t connectionId) { diff --git a/device/src/connections.h b/device/src/connections.h index 12f83ef70..b015ae099 100644 --- a/device/src/connections.h +++ b/device/src/connections.h @@ -69,6 +69,7 @@ typedef struct { uint8_t rxIdx; uint8_t txIdx; + bool rxIdxValid; // rxIdx holds the watermark of a frame accepted since the last reset } ATTR_PACKED connection_watermarks_t; typedef struct { diff --git a/device/src/messenger.c b/device/src/messenger.c index 8bad0d283..e68d27890 100644 --- a/device/src/messenger.c +++ b/device/src/messenger.c @@ -377,7 +377,18 @@ bool processWatermarks(uint8_t srcConnectionId, uint8_t src, const uint8_t* data return false; } - Connections[srcConnectionId].watermarks.rxIdx = data[offset+MessageOffset_Wm]; + connection_watermarks_t* wm = &Connections[srcConnectionId].watermarks; + uint8_t rxIdx = data[offset+MessageOffset_Wm]; + + // A frame whose ack got lost is resent with the same watermark; don't apply it twice + // (key states carry cursor deltas). rxIdxValid guards the first frame after a local + // watermark reset, whose rxIdx is unrelated to what the peer is sending. + if (wm->rxIdxValid && rxIdx == wm->rxIdx) { + return false; + } + + wm->rxIdx = rxIdx; + wm->rxIdxValid = true; return true; } From ea342106517c32044e3d785eef46a8b29a1dc5de Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 18:21:36 +0200 Subject: [PATCH 04/24] Bridge: first resend at 15ms instead of 64ms. The ack loop is ~3ms for a key-state frame and ~13ms for a maximum-length one; every retry blinds the left key scanner for the whole delay. Backoff still doubles per retry. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 02be9b89b..af814c96a 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -20,7 +20,10 @@ #define THREAD_PRIORITY -5 #define UART_FOREVER_TIMEOUT 10000 -#define UART_RESEND_DELAY 64 +// First resend after this many ms, doubling on every retry. The ack loop takes ~3ms for a +// key-state frame and ~13ms for a maximum-length one (115200 baud), so 15ms is late enough +// not to duplicate a frame that's merely still in flight, and the backoff handles a bad link. +#define UART_RESEND_DELAY 15 #define UART_RESEND_COUNT 5 typedef enum { @@ -318,7 +321,7 @@ static void sendControl(uart_state_t *uartState, uint8_t byte, bool isAck) { // wakePeer: a nack-triggered resend skips the wake handshake, since the peer just parsed // our garbled frame and is provably awake; a timeout-triggered one redoes it, because -// after 64ms+ of silence the peer has almost certainly slept again. This must not +// after the resend delay of silence the peer may have slept again. This must not // k_sleep - it runs on the control thread, where blocking makes us blind to wake edges, // acks and pings, which used to cascade into a disconnect + BLE-fallback feedback loop. static void resend(uart_state_t *uartState, bool wakePeer) { From b386b9eb5848f4abc8813464d2280b1c87cbfe56 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 18:45:59 +0200 Subject: [PATCH 05/24] Fix DEBUG_STRESS_UART having no effect. shared/uart_parser.c never included debug.h, so the flag was undefined there and the byte-corruption block was compiled out regardless of its value (since a689d1f05). Co-Authored-By: Claude Fable 5.1 --- shared/uart_parser.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/shared/uart_parser.c b/shared/uart_parser.c index c6c789fd5..92ef6e1ca 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -11,8 +11,10 @@ #ifdef DEVICE_ID #include "logger.h" +#include "debug.h" // DEBUG_STRESS_UART #else #define LogU(...) +#define DEBUG_STRESS_UART false #endif #define CRC_SALT 0x1234 From b1ec0c48fb35fc2bc1fc2684d3de7917055c3d33 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 29 Sep 2026 19:09:59 +0200 Subject: [PATCH 06/24] Bridge: keep uart_tx buffers alive until the transfer completes. uart_tx stores the buffer pointer and returns; EasyDMA reads it afterwards. Control bytes (Ack/Nack/Ping) and the wake byte were sent from stack variables that went out of scope before the transfer, so what reached the wire was not guaranteed. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 6 +++++- device/src/keyboard/uart_link.c | 3 ++- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index af814c96a..4a8edce43 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -59,6 +59,9 @@ typedef struct { uint8_t* rxBuffer; uint8_t txBuffer[UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH]; + // uart_tx reads its buffer by DMA after returning; it has to outlive the call. Control + // bytes are serialized by txControlBusy, so one slot is enough. + uint8_t controlByte; struct k_sem txBufferBusy; struct k_sem controlThreadSleeper; @@ -311,7 +314,8 @@ static void sendControl(uart_state_t *uartState, uint8_t byte, bool isAck) { // Measured once we hold the TX slot: includes waiting out our own in-flight frame. recordLatency(&stats.ackTurn, uartState->ackReqCyc); } - int err = UartLink_Send(&uartState->core, &byte, 1); + uartState->controlByte = byte; + int err = UartLink_Send(&uartState->core, &uartState->controlByte, 1); if (err != 0) { // No transfer started -> no TX_DONE -> return the slot ourselves. stats.txSendFail++; diff --git a/device/src/keyboard/uart_link.c b/device/src/keyboard/uart_link.c index e9fa11f56..47f8fe372 100644 --- a/device/src/keyboard/uart_link.c +++ b/device/src/keyboard/uart_link.c @@ -266,7 +266,8 @@ void UartLink_SendWakeByte(uart_link_t *uartState) { return; } - uint8_t wake = UartControlByte_Wake; + // uart_tx reads its buffer by DMA after returning; a stack byte doesn't outlive the call. + static uint8_t wake = UartControlByte_Wake; UartLink_LockBusy(uartState); int err = uart_tx(uartState->device, &wake, 1, UART_TRANSPORT_TIMEOUT_US); if (err != 0) { From c310733951dda0b3f86c8458c28ecbf9897a807d Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 30 Sep 2026 11:53:24 +0200 Subject: [PATCH 07/24] Bridge: dump invalid frames as lines, not one log message per byte. The CRC-invalid dump ran in the UART RX ISR and emitted one deferred log message per byte; a single bad frame overflowed the log buffer regardless of log thread priority. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 40 ++++++++++++++++++++++++++----- shared/uart_parser.c | 2 +- 2 files changed, 35 insertions(+), 7 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 4a8edce43..a9e48461a 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -1,3 +1,4 @@ +#include #include #include #include @@ -186,6 +187,37 @@ static void setRxState(uart_state_t *uartState, uart_rx_state_t state) { wakeControlThread(uartState); } +// Dumps a frame as a few log lines rather than one log message per byte: this runs in the +// UART ISR, and a per-byte dump floods the deferred log buffer faster than any log thread +// priority can drain it. Only the head of the frame is shown. +#define FRAME_DUMP_LINE_LEN 80 +#define FRAME_DUMP_MAX_LINES 2 + +static void logFrameBytes(const uint8_t* data, uint16_t len) { + char line[FRAME_DUMP_LINE_LEN]; + uint16_t pos = 0; + uint16_t shown = len; + uint16_t lines = 0; + + for (uint16_t i = 0; i < shown; i++) { + int n = snprintf(line + pos, FRAME_DUMP_LINE_LEN - pos, "%02x ", data[i]); + bool lineFull = n < 0 || pos + n >= sizeof(line) - 1; + if (lineFull) { + line[pos] = '\0'; + LogU(" %s\n", line); + pos = 0; + if (++lines >= FRAME_DUMP_MAX_LINES) { + break; + } + n = snprintf(line, sizeof(line), "%02x ", data[i]); + } + pos += n; + } + if (pos > 0) { + LogU(" %s%s\n", line, shown < len ? "..." : ""); + } +} + static void receiveMessage(void *state, uart_control_t messageKind, const uint8_t* data, uint16_t len) { uart_state_t *uartState = (uart_state_t *)state; @@ -236,12 +268,8 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ uartState->invalidMessagesCounter++; const char *out1, *out2; Messenger_GetMessageDescription(uartState->rxBuffer, 0, &out1, &out2); - LogUO("Crc-invalid UART message received! %s %s ", out1, out2 == NULL ? "" : out2); - - for (uint16_t i = 0; i < uartState->parser.rxPosition; i++) { - LogU("%i ", uartState->rxBuffer[i]); - } - LogU("\n"); + LogUO("Crc-invalid UART message received! %s %s\n", out1, out2 == NULL ? "" : out2); + logFrameBytes(uartState->rxBuffer, uartState->parser.rxPosition); setRxState(uartState, UartRxState_Nack); diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 92ef6e1ca..af0e7ec83 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -58,7 +58,7 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { uint8_t r2 = get_random(); if (r1 < 128) { - LogU("Oops!\n"); + LogU("UartStress: Oops!\n"); byte = byte ^ r2; } #endif From 33c22343f971a6b768199e98a95c083045386b21 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 30 Sep 2026 14:49:34 +0200 Subject: [PATCH 08/24] Bridge: constant resend delay, three retries. The exponential backoff let one unacked frame hold txBufferBusy for ~1s (was ~8s at 64ms); on the left half that blocks the key scanner, so key changes made meanwhile are coalesced or lost. Worst case is now UART_RESEND_COUNT * UART_RESEND_DELAY = 45ms. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/uart_bridge.c | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index a9e48461a..db70343ea 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -21,11 +21,18 @@ #define THREAD_PRIORITY -5 #define UART_FOREVER_TIMEOUT 10000 -// First resend after this many ms, doubling on every retry. The ack loop takes ~3ms for a -// key-state frame and ~13ms for a maximum-length one (115200 baud), so 15ms is late enough -// not to duplicate a frame that's merely still in flight, and the backoff handles a bad link. +// Resend an unacked frame every UART_RESEND_DELAY ms, up to UART_RESEND_COUNT times, then +// give up. The ack loop takes ~3ms for a key-state frame and ~13ms for a maximum-length one +// (115200 baud), so 15ms is late enough not to duplicate a frame that's merely in flight. +// +// The delay is constant, not exponential, on purpose. Senders block on txBufferBusy (one +// slot) until the outstanding frame is acked; on the left half that sender is the key +// scanner thread, which then stops scanning - key changes made during the stall are +// coalesced into the next snapshot or, if pressed and released inside it, never seen. The +// worst-case stall is therefore UART_RESEND_COUNT * UART_RESEND_DELAY (was ~8s with the old +// 64ms<txState == UartTxState_WaitingForAck) { - uint32_t resendDelay = (UART_RESEND_DELAY << uartState->resendTries); + uint32_t resendDelay = UART_RESEND_DELAY; uint32_t resendTime = uartState->lastMessageSentTime + resendDelay; if (currentTime >= resendTime) { LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); From 94fd761276868b243415300389da8db0cb2b06eb Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 30 Sep 2026 14:51:46 +0200 Subject: [PATCH 09/24] BridgeStress: simulate dropped control bytes with higher probability. Under DEBUG_STRESS_UART, ack/nack/ping bytes are discarded with ~5% probability, so the timeout -> resend -> duplicate path gets exercised, not only CRC failures. Co-Authored-By: Claude Fable 5.1 --- device/src/keyboard/key_scanner.c | 2 ++ shared/uart_parser.c | 13 +++++++++++++ 2 files changed, 15 insertions(+) diff --git a/device/src/keyboard/key_scanner.c b/device/src/keyboard/key_scanner.c index c213071c6..3f36caf61 100644 --- a/device/src/keyboard/key_scanner.c +++ b/device/src/keyboard/key_scanner.c @@ -301,6 +301,8 @@ static void scanAllKeys() { } if (DEVICE_IS_UHK80_LEFT) { + // If ack gets lost, second key state change will block (because uart is busy with control of the first one). That blocks us. Third keystate change may be lost. + // TODO: consider passing this via postponer queue. Messenger_Send2(DeviceId_Uhk80_Right, MessageId_SyncableProperty, SyncablePropertyId_LeftHalfKeyStates, compressedBuffer, compressedLength); } } diff --git a/shared/uart_parser.c b/shared/uart_parser.c index af0e7ec83..2e808df76 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -56,11 +56,24 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { #if DEBUG_STRESS_UART uint16_t r1 = get_random(); uint8_t r2 = get_random(); + uint16_t r3 = get_random(); + // Mutate byte if (r1 < 128) { LogU("UartStress: Oops!\n"); byte = byte ^ r2; } + + // Or drop the byte + if (r3 < 128) { + return; + } + + // More dropped acks, more fun: CRC mutation alone never reaches the resend path. + bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Nack; + if (r3 < 2048 && isAckLike && !uartState->receivingMessage) { + return; + } #endif From fdee18a4bf4ca0629bbb01ecff4e32ae425cc410 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Thu, 1 Oct 2026 01:57:49 +0200 Subject: [PATCH 10/24] Bridge: recompute the resend deadline after resending. uartLoop took its sleep deadline before the resend branch, and resend() restamps lastMessageSentTime, so after every retry the thread slept to the next ping tick instead of to the next retry. The effective retry interval was therefore max(UART_RESEND_DELAY, time to next ping) == UART_BRIDGE_PING_INTERVAL == 200ms, which the logs show verbatim: gaps of 20/80/200/200ms against a nominal 15ms. That made the retry path unable to recover anything: five transmissions at 200ms is 1000ms against a 700ms UART_BRIDGE_TIMEOUT, so the link was always declared dead mid-retry, which then triggered a BLE fallback and a StateSync link reset - a burst of frames that lost another ack, and round again. Latent since at least 17.1.3; it only bit once the delay dropped below the ping interval (64ms << tries against a 100ms ping only quantised the first retry). Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index db70343ea..660e9a64f 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -475,15 +475,17 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { } currentTime = k_uptime_get(); + bool ackOverdue = uartState->txState == UartTxState_WaitingForAck + && currentTime >= uartState->lastMessageSentTime + UART_RESEND_DELAY; + if (ackOverdue) { + LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, UART_RESEND_DELAY); + resend(uartState, true); + } + + // Must be taken after the resend, which restamps lastMessageSentTime - read + // earlier, the deadline lands on the next ping tick instead of the next retry. if (uartState->txState == UartTxState_WaitingForAck) { - uint32_t resendDelay = UART_RESEND_DELAY; - uint32_t resendTime = uartState->lastMessageSentTime + resendDelay; - if (currentTime >= resendTime) { - LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); - resend(uartState, true); - } else { - wakeTime = MIN(wakeTime, resendTime); - } + wakeTime = MIN(wakeTime, uartState->lastMessageSentTime + UART_RESEND_DELAY); } } else { uartState->txState = UartTxState_Idle; From 00bd5da0dd75da1c3744c7933f1cd9fa816d701d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Thu, 1 Oct 2026 01:57:57 +0200 Subject: [PATCH 11/24] Bridge: reset resendTries when the link goes down. resendTries was cleared only on an ack or on give-up, so a burst that disconnected mid-retry left it at UART_RESEND_COUNT+1. The first frame sent after the reconnect then hit the give-up branch on its very first timeout and was discarded. Visible in the logs as a "Repeatedly failed to send a message!" immediately after the first "didn't receive ack" of each burst, rather than after the fifth. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 660e9a64f..bd19fdb4a 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -490,6 +490,8 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { } else { uartState->txState = UartTxState_Idle; uartState->rxState = UartRxState_Idle; + // The retry budget belongs to the frame, not to the link. + uartState->resendTries = 0; } currentTime = k_uptime_get(); From 811a684509d6d4e92990b828c377d2bd5e772194 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Thu, 1 Oct 2026 01:58:08 +0200 Subject: [PATCH 12/24] Bridge: assert the resend budget fits inside the link timeout. The retry budget and UART_BRIDGE_TIMEOUT were independent constants, and had drifted into a state where the budget could not complete: 5 transmissions x 200ms effective delay against a 700ms timeout. With the delay fixed it is 5 x 15 = 75ms, but nothing stopped the two from drifting apart again. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index bd19fdb4a..f9e131956 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -34,6 +34,12 @@ #define UART_RESEND_DELAY 15 #define UART_RESEND_COUNT 3 +// A frame gets UART_RESEND_COUNT+2 transmissions, so the budget spans that many delays. It +// must fit inside UART_BRIDGE_TIMEOUT, or the link dies before the retries are exhausted. +#define UART_RESEND_BUDGET_MS ((UART_RESEND_COUNT + 2) * UART_RESEND_DELAY) +_Static_assert(UART_RESEND_BUDGET_MS < UART_BRIDGE_TIMEOUT, + "UART resend budget outlives UART_BRIDGE_TIMEOUT"); + typedef enum { UartTxState_Idle, UartTxState_WaitingForAck, From 5229e08f46394e6bc10bdfe9fdff674143f2be77 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Thu, 1 Oct 2026 02:02:20 +0200 Subject: [PATCH 13/24] Bridge: key acks to the acked frame's watermark parity. An ack was a bare control byte with no sequence information, and the sender closed whatever frame happened to be outstanding. A resend produces two acks for one frame - the peer acks the duplicate too, because the ack is raised in the UART layer before the messenger's watermark dedup runs - so the second ack closed the *next* frame: L sends F1 waiting L resends F1 (timeout) waiting ack(F1) arrives -> closes F1 sender pushes F2 ack(dup F1) arrives -> closes F2 F2 may still be on the wire ack(F2) arrives -> closes F3 ... permanently one frame ahead While desynchronised the link has no error detection at all: a genuinely lost frame gets its predecessor's trailing ack and is never resent, so a dropped key-state frame disappears silently. The stream only resynchronises when an ack lands with nothing outstanding, which a StateSync reset burst never allows. 344e84e6a fixed the duplicate *delivery* half of this; this is the ack aliasing half. A single bit is enough, since the window is one frame. Two new control bytes carry it - UartControlByte_Ack0 for an even watermark, Ack1 for an odd one - and an ack whose parity does not match the outstanding frame is counted as stale and ignored. It also makes the desync observable: ackWhileIdle cannot see it, because in that state the acks are never idle-time ones. The pre-existing UartControlByte_Ack keeps its value and its unsequenced behaviour, so a peer that predates Ack0/Ack1 is still understood and needs no flag day. Note the compatibility is one-directional: such a peer cannot parse Ack0/Ack1 and will read them as out-of-frame bytes, so a mixed pair still degrades in that direction. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 44 ++++++++++++++++++++++++------- shared/module/uart.c | 2 ++ shared/uart_parser.c | 19 ++++++++++++- shared/uart_parser.h | 7 +++++ 4 files changed, 61 insertions(+), 11 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index f9e131956..045e5d5a0 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -66,6 +66,8 @@ typedef struct { uint32_t lastPingTime; uint16_t invalidMessagesCounter; uint8_t resendTries; + uint8_t txWm; // watermark of the frame we await an ack for + uint8_t rxWm; // watermark of the frame we owe an ack for // Cycle stamps for the latency stats below. uint32_t sentCyc; // last uart_tx of a data frame @@ -109,6 +111,7 @@ typedef struct { uint32_t framesSent; uint32_t framesReceived; uint16_t ackWhileIdle; // ack arrived while we weren't waiting for one + uint16_t ackStale; // ack for a frame other than the outstanding one uint16_t nackWhileIdle; uint16_t nackReceived; uint16_t resendTimeout; @@ -237,13 +240,30 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ uartState->lastLinkActivity = k_uptime_get(); switch (messageKind) { case UartControl_Ack: - if (uartState->txState == UartTxState_WaitingForAck) { - recordLatency(&stats.ackLoop, uartState->sentCyc); - uartState->resendTries = 0; - uartState->txState = UartTxState_Idle; - k_sem_give(&uartState->txBufferBusy); - } else { - stats.ackWhileIdle++; + case UartControl_Ack0: + case UartControl_Ack1: { + // Ack0/Ack1 are matched by watermark parity: a resend is acked twice, and the + // second ack must not close the next frame. A bare Ack carries no parity and + // is accepted unconditionally, as it was before Ack0/Ack1 existed. + bool carriesParity = messageKind != UartControl_Ack; + bool ackIsOdd = messageKind == UartControl_Ack1; + bool acksOutstandingFrame = + !carriesParity || ackIsOdd == ((uartState->txWm & 1) != 0); + bool waiting = uartState->txState == UartTxState_WaitingForAck; + + if (waiting && acksOutstandingFrame) { + recordLatency(&stats.ackLoop, uartState->sentCyc); + uartState->resendTries = 0; + uartState->txState = UartTxState_Idle; + k_sem_give(&uartState->txBufferBusy); + } else if (waiting) { + stats.ackStale++; + if (stats.ackStale == 1) { + LogU("Uart: ack watermark mismatch\n"); + } + } else { + stats.ackWhileIdle++; + } } break; case UartControl_Nack: @@ -263,6 +283,7 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ uartState->lastPingTime = k_uptime_get(); stats.framesReceived++; uartState->ackReqCyc = k_cycle_get_32(); + uartState->rxWm = len > MessageOffset_Wm ? data[MessageOffset_Wm] : 0; setRxState(uartState, UartRxState_Ack); // message @@ -328,6 +349,7 @@ int UartBridge_SendMessage(message_t* msg) { UartLink_LockBusy(&uartState->core); Messenger_UpdateWatermarks(msg); + uartState->txWm = msg->wm; UartParser_StartMessage(&uartState->parser); UartParser_AppendEscapedTxBytes(&uartState->parser, (uint8_t[]){msg->src, msg->dst, msg->wm}, 3); UartParser_AppendEscapedTxBytes(&uartState->parser, msg->messageId, msg->idsUsed); @@ -464,7 +486,8 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (Connections_IsReady(uartState->connectionId)) { switch (uartState->rxState) { case UartRxState_Ack: - sendControl(uartState, UartControlByte_Ack, true); + sendControl(uartState, + (uartState->rxWm & 1) ? UartControlByte_Ack1 : UartControlByte_Ack0, true); uartState->rxState = UartRxState_Idle; break; case UartRxState_Nack: @@ -662,8 +685,9 @@ void UartBridge_DumpStats(void) { LogU(" frames: sent=%u received=%u crcInvalid=%u unexpectedBytes=%u\n", (unsigned)stats.framesSent, (unsigned)stats.framesReceived, (unsigned)uartState->invalidMessagesCounter, (unsigned)stats.unexpectedBytes); - LogU(" acks: whileIdle=%u nack=%u nackWhileIdle=%u\n", - (unsigned)stats.ackWhileIdle, (unsigned)stats.nackReceived, (unsigned)stats.nackWhileIdle); + LogU(" acks: whileIdle=%u stale=%u nack=%u nackWhileIdle=%u\n", + (unsigned)stats.ackWhileIdle, (unsigned)stats.ackStale, (unsigned)stats.nackReceived, + (unsigned)stats.nackWhileIdle); LogU(" resends: timeout=%u nack=%u giveUps=%u txSendFail=%u txAborted=%u\n", (unsigned)stats.resendTimeout, (unsigned)stats.resendNack, (unsigned)stats.giveUps, (unsigned)stats.txSendFail, (unsigned)core->txAbortedCount); diff --git a/shared/module/uart.c b/shared/module/uart.c index 7fd3ad2eb..ba2c90016 100644 --- a/shared/module/uart.c +++ b/shared/module/uart.c @@ -90,6 +90,8 @@ void ModuleUart_OnTime(void) { static void processDeserializedRxData(void *state, uart_control_t messageKind, const uint8_t* data, uint16_t len) { switch (messageKind) { case UartControl_Ack: + case UartControl_Ack0: + case UartControl_Ack1: case UartControl_Nack: case UartControl_Ping: case UartControl_InvalidMessage: diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 2e808df76..6f8a331d6 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -70,7 +70,8 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { } // More dropped acks, more fun: CRC mutation alone never reaches the resend path. - bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Nack; + bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Ack0 + || byte == UartControlByte_Ack1 || byte == UartControlByte_Nack; if (r3 < 2048 && isAckLike && !uartState->receivingMessage) { return; } @@ -85,6 +86,20 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { uartState->receiveMessage(uartState->userArg, UartControl_Ack, NULL, 0); break; + case UartControlByte_Ack0: + if (uartState->receivingMessage) { + goto msg_byte; + } + + uartState->receiveMessage(uartState->userArg, UartControl_Ack0, NULL, 0); + break; + case UartControlByte_Ack1: + if (uartState->receivingMessage) { + goto msg_byte; + } + + uartState->receiveMessage(uartState->userArg, UartControl_Ack1, NULL, 0); + break; case UartControlByte_Nack: if (uartState->receivingMessage) { goto msg_byte; @@ -189,6 +204,8 @@ static void escapeAndAppend(uart_parser_t *uartState, uint8_t byte) { case UartControlByte_End: case UartControlByte_Escape: case UartControlByte_Ack: + case UartControlByte_Ack0: + case UartControlByte_Ack1: case UartControlByte_Nack: case UartControlByte_Ping: case UartControlByte_Wake: diff --git a/shared/uart_parser.h b/shared/uart_parser.h index df40b11ed..7a0ad2de2 100644 --- a/shared/uart_parser.h +++ b/shared/uart_parser.h @@ -15,6 +15,8 @@ typedef enum { UartControl_Ack = 1, + UartControl_Ack0, + UartControl_Ack1, UartControl_Nack, UartControl_Ping, UartControl_ValidMessage, @@ -26,11 +28,16 @@ UartControlByte_Start = 0b01010100, UartControlByte_End = 0b01010101, UartControlByte_Escape = 0b01010110, + // Unsequenced ack. Kept for peers that predate Ack0/Ack1; we still accept it, but + // no longer send it. UartControlByte_Ack = 0b01010111, UartControlByte_Nack = 0b01011000, UartControlByte_Ping = 0b01011001, // Sacrificial byte sent to wake a sleeping (RX-disabled) peer. UartControlByte_Wake = 0b01011010, + // Ack carrying the low bit of the acked frame's watermark. + UartControlByte_Ack0 = 0b01011011, + UartControlByte_Ack1 = 0b01011100, } uart_control_byte_t; typedef struct { From 73e7b27c911c7fecfc506c58672380690c67de77 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Fri, 2 Oct 2026 11:44:03 +0200 Subject: [PATCH 14/24] Bridge: charge the frame's wire time to the resend deadline separately. The deadline is anchored where uart_tx starts the DMA, not where the transfer completes, so the frame's own time on the wire was being spent out of the ack budget. A maximum-length frame occupies the wire for ~23ms on its own, which expires a 15ms timer before the peer has finished receiving it - no collision with another frame required. UART_RESEND_DELAY now means what its comment claims: the ack turnaround alone. The wire time is computed from the frame length and added, which is exact to within microseconds since transmission time is just byte count times baud - and is a smaller change than hooking UART_TX_DONE, which would also have to tell a data frame's completion apart from an ack's and would add ISR latency to the same number. Measured on a healthy pair for calibration: ack turnaround 133us-1815us mean, 10.3ms worst case, against ackLoop maxima of 12.1-13.3ms that were nearly all frame transmission. The budget assert now uses the worst-case frame, so it stays honest: 5 * (15 + 24) = 195ms against UART_BRIDGE_TIMEOUT 700ms. UART_BYTE_TIME_US moves to the header on the way, since it is a property of the link rather than of the low-power scheme that happened to contain it. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 19 +++++++++++++++---- device/src/keyboard/uart_link.c | 3 --- device/src/keyboard/uart_link.h | 4 ++++ 3 files changed, 19 insertions(+), 7 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 045e5d5a0..6fc9725c9 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -34,9 +34,18 @@ #define UART_RESEND_DELAY 15 #define UART_RESEND_COUNT 3 +// UART_RESEND_DELAY budgets the ack turnaround only. The frame's own time on the wire has to +// be added on top, because the deadline is anchored where uart_tx starts the DMA, not where +// the transfer completes - measured ack turnaround is ~0.2-10ms, while a maximum-length frame +// alone occupies the wire for ~23ms. +#define UART_FRAME_WIRE_TIME_MS(BYTES) (((BYTES) * UART_BYTE_TIME_US + 999) / 1000) +#define UART_MAX_FRAME_WIRE_TIME_MS \ + UART_FRAME_WIRE_TIME_MS(UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH) + // A frame gets UART_RESEND_COUNT+2 transmissions, so the budget spans that many delays. It // must fit inside UART_BRIDGE_TIMEOUT, or the link dies before the retries are exhausted. -#define UART_RESEND_BUDGET_MS ((UART_RESEND_COUNT + 2) * UART_RESEND_DELAY) +#define UART_RESEND_BUDGET_MS \ + ((UART_RESEND_COUNT + 2) * (UART_RESEND_DELAY + UART_MAX_FRAME_WIRE_TIME_MS)) _Static_assert(UART_RESEND_BUDGET_MS < UART_BRIDGE_TIMEOUT, "UART resend budget outlives UART_BRIDGE_TIMEOUT"); @@ -504,17 +513,19 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { } currentTime = k_uptime_get(); + uint32_t resendDelay = + UART_RESEND_DELAY + UART_FRAME_WIRE_TIME_MS(uartState->parser.txPosition); bool ackOverdue = uartState->txState == UartTxState_WaitingForAck - && currentTime >= uartState->lastMessageSentTime + UART_RESEND_DELAY; + && currentTime >= uartState->lastMessageSentTime + resendDelay; if (ackOverdue) { - LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, UART_RESEND_DELAY); + LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); resend(uartState, true); } // Must be taken after the resend, which restamps lastMessageSentTime - read // earlier, the deadline lands on the next ping tick instead of the next retry. if (uartState->txState == UartTxState_WaitingForAck) { - wakeTime = MIN(wakeTime, uartState->lastMessageSentTime + UART_RESEND_DELAY); + wakeTime = MIN(wakeTime, uartState->lastMessageSentTime + resendDelay); } } else { uartState->txState = UartTxState_Idle; diff --git a/device/src/keyboard/uart_link.c b/device/src/keyboard/uart_link.c index 47f8fe372..3ef7e3357 100644 --- a/device/src/keyboard/uart_link.c +++ b/device/src/keyboard/uart_link.c @@ -125,9 +125,6 @@ void UartLink_Enable(uart_link_t *uartState) { #if UART_LOWPOWER -// One byte-time on the wire at 115200-8N1 (~87us), rounded up. -#define UART_BYTE_TIME_US 90 - // Edge-sense ISR: an incoming start bit on the slept RXD pin. Deliberately minimal - it // only kicks the owning thread and touches no lpState/gpio, so it cannot race // SleepRx/WakeRx. It re-fires on each edge of the wake byte until WakeRx disarms it; diff --git a/device/src/keyboard/uart_link.h b/device/src/keyboard/uart_link.h index 63e6cda7d..d29d8ee5d 100644 --- a/device/src/keyboard/uart_link.h +++ b/device/src/keyboard/uart_link.h @@ -41,6 +41,10 @@ // UART_WAKE_DISPATCH_DELAY_US, or that stop lands on the frame following a wake byte. #define UART_TRANSPORT_TIMEOUT_US 700 + // One byte-time on the wire at 115200-8N1 (~87us), rounded up. A physical property of the + // link, so it outlives the low-power scheme above it. + #define UART_BYTE_TIME_US 90 + // Typedefs: typedef enum { From 8b3296c9a9c1d2224c30574bde3e55fced9c4a37 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Fri, 2 Oct 2026 17:16:49 +0200 Subject: [PATCH 15/24] Fix DEBUG_STRESS_UART having no effect, properly this time. 9265da9aa added `#include "debug.h"` to shared/uart_parser.c to make the flag visible, but put it *inside* `#ifdef DEVICE_ID` - and that guard is itself always false there, because DEVICE_ID comes from CONFIG_DEVICE_ID via device.h, which the file never includes. So the `#else` branch kept defining DEBUG_STRESS_UART to false locally and the whole stress block stayed compiled out. Confirmed by the compile line carrying no -DDEVICE_ID, and by the injector's log string being absent from the ELF before this change and present after. The harness has therefore never run since a689d1f05, 9265da9aa and 501955053 notwithstanding. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- shared/uart_parser.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 6f8a331d6..45c934666 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -9,6 +9,11 @@ #include "shared/module/uart_link.h" #endif +// DEVICE_ID comes from CONFIG_DEVICE_ID via device.h. Without this include the guard below +// is always false, which silently compiles out DEBUG_STRESS_UART - the actual reason the +// stress harness had no effect, and what 9265da9aa missed by adding debug.h *inside* it. +#include "device.h" + #ifdef DEVICE_ID #include "logger.h" #include "debug.h" // DEBUG_STRESS_UART From 29a4ea4f8fdd0d95d39406168d4f4d5ed1e24b3c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Sun, 4 Oct 2026 16:10:38 +0200 Subject: [PATCH 16/24] Bridge: lower the resend delay to 7ms, and derive the timings by macro. With the frame's wire time charged separately, UART_RESEND_DELAY budgets the ack turnaround alone - measured at 133-346us mean with a sub-millisecond p90 on the left half and 1.8ms mean on the right. 15ms was sized against the observed maximum (~10ms, which was slot contention during a StateSync burst); sizing against the mean instead puts 7ms at roughly 20x it, and brings the recovery latency on a genuine loss into the same range as the 7ms NUS figure. The asymmetry justifies it: a spurious duplicate is cheap now that acks carry a watermark parity and no longer alias the ack stream, whereas the delay is also how long the sender stalls on a real loss, which blocks the key scanner. UART_RESEND_DELAY, UART_RESEND_COUNT, UART_BYTE_TIME_US and the wire-time helper move to uart_defs.h so the link tests can derive their own spacing from them instead of restating it. The stress injection rates become macros for the same reason, and the ack-drop rate goes from 1/32 to 1/16: over a link test's ~420 frames that puts two consecutive drops at ~80% per run and three at ~10%. Those cannot both be made comfortable - P(k drops) scales as p^k, so the separation between k and k+1 is only a factor of p. Budget assert still holds: 5 * (7 + 24) = 155ms against UART_BRIDGE_TIMEOUT 700ms. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 21 +++------------------ device/src/keyboard/uart_link.h | 3 --- shared/uart_defs.h | 21 +++++++++++++++++++++ shared/uart_parser.c | 21 ++++++++++++++++++--- 4 files changed, 42 insertions(+), 24 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 6fc9725c9..d78923eda 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -21,24 +21,9 @@ #define THREAD_PRIORITY -5 #define UART_FOREVER_TIMEOUT 10000 -// Resend an unacked frame every UART_RESEND_DELAY ms, up to UART_RESEND_COUNT times, then -// give up. The ack loop takes ~3ms for a key-state frame and ~13ms for a maximum-length one -// (115200 baud), so 15ms is late enough not to duplicate a frame that's merely in flight. -// -// The delay is constant, not exponential, on purpose. Senders block on txBufferBusy (one -// slot) until the outstanding frame is acked; on the left half that sender is the key -// scanner thread, which then stops scanning - key changes made during the stall are -// coalesced into the next snapshot or, if pressed and released inside it, never seen. The -// worst-case stall is therefore UART_RESEND_COUNT * UART_RESEND_DELAY (was ~8s with the old -// 64ms<receivingMessage) { + if (r3 < STRESS_ACK_DROP_THRESHOLD && isAckLike && !uartState->receivingMessage) { return; } #endif From d02cd216b5abe853585a125bf4c68524e60a7eae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Sun, 4 Oct 2026 16:35:50 +0200 Subject: [PATCH 17/24] Bridge: five retries, and make UART_RESEND_COUNT mean what it says. The give-up test was `resendTries++ > UART_RESEND_COUNT`, so a count of 3 actually permitted four resends and the budget macro carried a +2 to compensate. Corrected to >=, so the constant is now the number of resends and a frame gets UART_RESEND_COUNT+1 transmissions. Raised to 5 at the same time, which the shorter delay pays for: 5 retries at 7ms plus wire time is a ~54ms worst-case sender stall, against ~85ms for the previous 4 at 15ms. More chances to recover a lost frame, in less time than before - and the stall matters because on the left half the blocked sender is the key scanner. Fixing the off-by-one in isolation would have been a behaviour change disguised as a rename; doing it alongside the deeper count makes the net effect an improvement on both axes. Budget assert: (5+1) * (7+24) = 186ms against UART_BRIDGE_TIMEOUT 700ms. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 9 +++++---- shared/uart_defs.h | 16 +++++++++++----- 2 files changed, 16 insertions(+), 9 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index d78923eda..5a9841b68 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -27,10 +27,11 @@ #define UART_MAX_FRAME_WIRE_TIME_MS \ UART_FRAME_WIRE_TIME_MS(UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH) -// A frame gets UART_RESEND_COUNT+2 transmissions, so the budget spans that many delays. It -// must fit inside UART_BRIDGE_TIMEOUT, or the link dies before the retries are exhausted. +// A frame gets UART_RESEND_COUNT+1 transmissions and the give-up lands one delay after the +// last, so the budget spans that many delays. It must fit inside UART_BRIDGE_TIMEOUT, or the +// link is declared dead before the retries are exhausted and no retry can ever recover it. #define UART_RESEND_BUDGET_MS \ - ((UART_RESEND_COUNT + 2) * (UART_RESEND_DELAY + UART_MAX_FRAME_WIRE_TIME_MS)) + ((UART_RESEND_COUNT + 1) * (UART_RESEND_DELAY + UART_MAX_FRAME_WIRE_TIME_MS)) _Static_assert(UART_RESEND_BUDGET_MS < UART_BRIDGE_TIMEOUT, "UART resend budget outlives UART_BRIDGE_TIMEOUT"); @@ -391,7 +392,7 @@ static void resend(uart_state_t *uartState, bool wakePeer) { } else { stats.resendNack++; } - if (uartState->resendTries++ > UART_RESEND_COUNT) { + if (uartState->resendTries++ >= UART_RESEND_COUNT) { stats.giveUps++; LogU("Repeatedly failed to send a message! "); for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { diff --git a/shared/uart_defs.h b/shared/uart_defs.h index 90d130696..b44303be4 100644 --- a/shared/uart_defs.h +++ b/shared/uart_defs.h @@ -40,7 +40,9 @@ #define UART_FRAME_WIRE_TIME_MS(BYTES) (((BYTES) * UART_BYTE_TIME_US + 999) / 1000) // Resend an unacked frame every UART_RESEND_DELAY ms (plus the frame's own time on the - // wire, which the sender adds), up to UART_RESEND_COUNT times, then give up. + // wire, which the sender adds), up to UART_RESEND_COUNT times, then give up. So a frame + // gets UART_RESEND_COUNT+1 transmissions in all, and the give-up lands on the + // (UART_RESEND_COUNT+1)th timeout. // // The delay budgets the ack turnaround alone. Measured on hardware, that is 133-346us // mean with a sub-millisecond p90 on the left half and 1.8ms mean on the right, so 7ms is @@ -49,11 +51,15 @@ // cheap now that acks carry a watermark parity, whereas the delay is also how long the // sender stalls on a genuine loss, and that blocks the key scanner. // - // Constant rather than exponential on purpose: the worst-case stall is - // UART_RESEND_COUNT * UART_RESEND_DELAY, and every retry shortens the blind window it - // causes rather than lengthening it. + // Constant rather than exponential on purpose: senders block on txBufferBusy until the + // frame is acked, and on the left half that sender is the key scanner, so the whole + // budget is a window in which key changes are coalesced or missed entirely. + // + // The shorter delay paid for the deeper retry count: 5 retries at 7ms+wire is a ~54ms + // worst case, against ~85ms for the previous 4 retries at 15ms+wire. More chances to + // recover a lost frame, in less time than before. #define UART_RESEND_DELAY 7 - #define UART_RESEND_COUNT 3 + #define UART_RESEND_COUNT 5 #define UART_MODULE_PING_INTERVAL_MS 500 #define UART_MODULE_TIMEOUT_MS (UART_MODULE_PING_INTERVAL_MS*4) From a4bcb2bea45002b08853a1ca732f8d0f71911d4a Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Mon, 5 Oct 2026 13:23:23 +0200 Subject: [PATCH 18/24] Bridge: clean AI code. --- adc_issue/saadc_deadlock_repro/CMakeLists.txt | 8 ++++++ device/src/connections.h | 2 +- device/src/keyboard/uart_bridge.c | 27 +++++-------------- device/src/messenger.c | 2 -- device/src/shell/shell_commands.c | 7 ++--- shared/uart_defs.h | 19 ------------- shared/uart_parser.c | 11 -------- 7 files changed, 20 insertions(+), 56 deletions(-) create mode 100644 adc_issue/saadc_deadlock_repro/CMakeLists.txt diff --git a/adc_issue/saadc_deadlock_repro/CMakeLists.txt b/adc_issue/saadc_deadlock_repro/CMakeLists.txt new file mode 100644 index 000000000..8232048c9 --- /dev/null +++ b/adc_issue/saadc_deadlock_repro/CMakeLists.txt @@ -0,0 +1,8 @@ +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.20.0) + +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(saadc_deadlock_repro) + +target_sources(app PRIVATE src/main.c) diff --git a/device/src/connections.h b/device/src/connections.h index b015ae099..a751ee4c5 100644 --- a/device/src/connections.h +++ b/device/src/connections.h @@ -69,7 +69,7 @@ typedef struct { uint8_t rxIdx; uint8_t txIdx; - bool rxIdxValid; // rxIdx holds the watermark of a frame accepted since the last reset + bool rxIdxValid; } ATTR_PACKED connection_watermarks_t; typedef struct { diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 5a9841b68..ec7860df1 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -22,18 +22,12 @@ #define UART_FOREVER_TIMEOUT 10000 -// UART_RESEND_DELAY / UART_RESEND_COUNT and the wire-time helper live in uart_defs.h, so -// that the link tests can derive their own timings from them rather than restating them. #define UART_MAX_FRAME_WIRE_TIME_MS \ UART_FRAME_WIRE_TIME_MS(UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH) -// A frame gets UART_RESEND_COUNT+1 transmissions and the give-up lands one delay after the -// last, so the budget spans that many delays. It must fit inside UART_BRIDGE_TIMEOUT, or the -// link is declared dead before the retries are exhausted and no retry can ever recover it. -#define UART_RESEND_BUDGET_MS \ - ((UART_RESEND_COUNT + 1) * (UART_RESEND_DELAY + UART_MAX_FRAME_WIRE_TIME_MS)) -_Static_assert(UART_RESEND_BUDGET_MS < UART_BRIDGE_TIMEOUT, - "UART resend budget outlives UART_BRIDGE_TIMEOUT"); +// Assert that the resend budet fits inside uart timeout +#define UART_RESEND_BUDGET_MS ((UART_RESEND_COUNT + 1) * (UART_RESEND_DELAY + UART_MAX_FRAME_WIRE_TIME_MS)) +_Static_assert(UART_RESEND_BUDGET_MS < UART_BRIDGE_TIMEOUT, "UART resend budget outlives UART_BRIDGE_TIMEOUT"); typedef enum { UartTxState_Idle, @@ -198,9 +192,6 @@ static void setRxState(uart_state_t *uartState, uart_rx_state_t state) { wakeControlThread(uartState); } -// Dumps a frame as a few log lines rather than one log message per byte: this runs in the -// UART ISR, and a per-byte dump floods the deferred log buffer faster than any log thread -// priority can drain it. Only the head of the frame is shown. #define FRAME_DUMP_LINE_LEN 80 #define FRAME_DUMP_MAX_LINES 2 @@ -481,8 +472,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (Connections_IsReady(uartState->connectionId)) { switch (uartState->rxState) { case UartRxState_Ack: - sendControl(uartState, - (uartState->rxWm & 1) ? UartControlByte_Ack1 : UartControlByte_Ack0, true); + sendControl(uartState, (uartState->rxWm & 1) ? UartControlByte_Ack1 : UartControlByte_Ack0, true); uartState->rxState = UartRxState_Idle; break; case UartRxState_Nack: @@ -499,17 +489,14 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { } currentTime = k_uptime_get(); - uint32_t resendDelay = - UART_RESEND_DELAY + UART_FRAME_WIRE_TIME_MS(uartState->parser.txPosition); - bool ackOverdue = uartState->txState == UartTxState_WaitingForAck - && currentTime >= uartState->lastMessageSentTime + resendDelay; + uint32_t resendDelay = UART_RESEND_DELAY + UART_FRAME_WIRE_TIME_MS(uartState->parser.txPosition); + bool ackOverdue = uartState->txState == UartTxState_WaitingForAck && currentTime >= uartState->lastMessageSentTime + resendDelay; if (ackOverdue) { LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); resend(uartState, true); } - // Must be taken after the resend, which restamps lastMessageSentTime - read - // earlier, the deadline lands on the next ping tick instead of the next retry. + // Must be taken after the resend, which restamps lastMessageSentTime if (uartState->txState == UartTxState_WaitingForAck) { wakeTime = MIN(wakeTime, uartState->lastMessageSentTime + resendDelay); } diff --git a/device/src/messenger.c b/device/src/messenger.c index e68d27890..9431d96a0 100644 --- a/device/src/messenger.c +++ b/device/src/messenger.c @@ -381,8 +381,6 @@ bool processWatermarks(uint8_t srcConnectionId, uint8_t src, const uint8_t* data uint8_t rxIdx = data[offset+MessageOffset_Wm]; // A frame whose ack got lost is resent with the same watermark; don't apply it twice - // (key states carry cursor deltas). rxIdxValid guards the first frame after a local - // watermark reset, whose rxIdx is unrelated to what the peer is sending. if (wm->rxIdxValid && rxIdx == wm->rxIdx) { return false; } diff --git a/device/src/shell/shell_commands.c b/device/src/shell/shell_commands.c index e371d7dc2..b22d5319f 100644 --- a/device/src/shell/shell_commands.c +++ b/device/src/shell/shell_commands.c @@ -24,9 +24,6 @@ #include "stubs.h" #include "slave_drivers/kboot_driver.h" #include "pin_wiring.h" -#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT -#include "keyboard/uart_bridge.h" -#endif #include "slot.h" #include "i2c_addresses.h" #include "test_suite/test_suite.h" @@ -42,6 +39,10 @@ #include #include +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT +#include "keyboard/uart_bridge.h" +#endif + shell_t Shell = { .keyLog = 0, .statLog = 0, diff --git a/shared/uart_defs.h b/shared/uart_defs.h index b44303be4..c653faf4c 100644 --- a/shared/uart_defs.h +++ b/shared/uart_defs.h @@ -39,25 +39,6 @@ #define UART_BYTE_TIME_US 90 #define UART_FRAME_WIRE_TIME_MS(BYTES) (((BYTES) * UART_BYTE_TIME_US + 999) / 1000) - // Resend an unacked frame every UART_RESEND_DELAY ms (plus the frame's own time on the - // wire, which the sender adds), up to UART_RESEND_COUNT times, then give up. So a frame - // gets UART_RESEND_COUNT+1 transmissions in all, and the give-up lands on the - // (UART_RESEND_COUNT+1)th timeout. - // - // The delay budgets the ack turnaround alone. Measured on hardware, that is 133-346us - // mean with a sub-millisecond p90 on the left half and 1.8ms mean on the right, so 7ms is - // roughly 20x the mean. It is deliberately not sized to the observed maximum (~10ms, - // which was slot contention during a StateSync burst): an occasional duplicate frame is - // cheap now that acks carry a watermark parity, whereas the delay is also how long the - // sender stalls on a genuine loss, and that blocks the key scanner. - // - // Constant rather than exponential on purpose: senders block on txBufferBusy until the - // frame is acked, and on the left half that sender is the key scanner, so the whole - // budget is a window in which key changes are coalesced or missed entirely. - // - // The shorter delay paid for the deeper retry count: 5 retries at 7ms+wire is a ~54ms - // worst case, against ~85ms for the previous 4 retries at 15ms+wire. More chances to - // recover a lost frame, in less time than before. #define UART_RESEND_DELAY 7 #define UART_RESEND_COUNT 5 diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 3d1ce14f5..79488c34c 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -9,9 +9,6 @@ #include "shared/module/uart_link.h" #endif -// DEVICE_ID comes from CONFIG_DEVICE_ID via device.h. Without this include the guard below -// is always false, which silently compiles out DEBUG_STRESS_UART - the actual reason the -// stress harness had no effect, and what 9265da9aa missed by adding debug.h *inside* it. #include "device.h" #ifdef DEVICE_ID @@ -22,14 +19,6 @@ #define DEBUG_STRESS_UART false #endif -// Fault-injection rates under DEBUG_STRESS_UART, as reciprocals of get_random()'s 16-bit -// range. Expressed as macros so the link tests can reason about them rather than guess. -// -// The ack-drop rate is the one that matters: a dropped ack is what forces a resend. The -// probability of k consecutive drops on one frame is STRESS_ACK_DROP^-k, so the separation -// between "k happens often" and "k+1 is rare" is only a factor of that probability - they -// cannot both be made comfortable. 1/16 over a link test's ~420 frames puts two consecutive -// drops at ~80% per run (exercising the absorb path) and three at ~10% (a false failure). #define STRESS_RANDOM_RANGE 65536 #define STRESS_BYTE_FAULT_RECIPROCAL 512 #define STRESS_ACK_DROP_RECIPROCAL 16 From 4f052ad8ed325ce9222334858547e4d4affc1810 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Mon, 5 Oct 2026 15:07:33 +0200 Subject: [PATCH 19/24] BridgeStress: log lost bytes. --- shared/uart_parser.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 79488c34c..cd42fe24e 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -75,6 +75,7 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { // Or drop the byte if (r3 < STRESS_BYTE_FAULT_THRESHOLD) { + LogU("UartStress: Oops lost!\n"); return; } @@ -82,6 +83,7 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Ack0 || byte == UartControlByte_Ack1 || byte == UartControlByte_Nack; if (r3 < STRESS_ACK_DROP_THRESHOLD && isAckLike && !uartState->receivingMessage) { + LogU("UartStress: Oops lost ack!\n"); return; } #endif From 629f662b1fd1842bf0f5088941a1b5704a012f98 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Karel=20Tu=C4=8Dek?= Date: Tue, 6 Oct 2026 13:46:32 +0200 Subject: [PATCH 20/24] LinkTest: test the left-right bridge under stress, across the real link. Both halves run the same link test script; each presses only the keys it owns, so what the right half validates has actually crossed the wire. The right sends MessengerCommand_StartTest before every repetition; the left picks it up in its scanner thread (starting it from the receive path raced the end of the previous run) and publishes its key states over the UART bridge on change only. Stress is switched on only between two quiet steps, so the StartTest exchange itself is never stressed - a dropped ack there resent it and restarted the left. Link tests are found by their id in any module (Tests_FindLinkTest, ids in tests.h). Link/probe: left change L1, left change L2 4ms later, right change R at 32ms that L2 must beat. Lost acks on L1 stall the sender, holding L2 back. Measured: a timeout retry ~9.3ms, a nack retry ~3ms, L2 lands ~6ms after the sender frees up, so R passes two consecutive timeouts and fails three. Two probes share a 40ms slot pair on six keys, every key phase clearing debounce. 70 cycles, sized so a healthy run fails ~20% of the time. Test suite: - Delays run on one schedule from the test's start (start plus all delays so far) instead of from when each began, so the ticks of other actions no longer drift the two halves apart. A doubletap test that only passed on that tick slack gets real debounce margin. - repeatCount: a repeated test runs exactly that many repetitions, counts each failing one once, is never auto-rerun and never verbose; timeouts are logged. A failing one reports e.g. "FAIL (2/70 failed, 98% fail confidence)", assuming a healthy test fails 20% of the time (binomial). The summary lists discrete and repeated tests separately, combining the repeated ones by Fisher's method (test_statistics.c, no libm). - The suite ticker is split into evaluating a test's outcome, concluding a repetition or a test, the verbose rerun, moving on and finishing the suite. - The left half logs none of a test's actions. Stress injection draws from xorshift32: the one-bit LFSR made the rolls of back-to-back acks share 13 of 16 bits, making two and three dropped acks in a row ~2x and ~4x likelier than nominal. The stress rates are marked as calibrated against by the link tests. uhk recover also dumps where the main thread sits (state, pc/lr, return addresses on its stack), to tell a blocked main from an idle one without a debugger. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01N5oDHHomxRbhs7jTqA9rgW --- device/src/keyboard/uart_bridge.c | 20 +- device/src/messenger.c | 4 + device/src/messenger.h | 1 + right/src/macros/debug_commands.c | 44 +++ right/src/test_suite/CLAUDE.md | 17 +- right/src/test_suite/CMakeLists.txt | 2 + right/src/test_suite/test_actions.h | 5 + right/src/test_suite/test_hooks.h | 4 + right/src/test_suite/test_input_machine.c | 91 +++-- right/src/test_suite/test_input_machine.h | 4 + right/src/test_suite/test_statistics.c | 106 ++++++ right/src/test_suite/test_statistics.h | 29 ++ right/src/test_suite/test_suite.c | 402 +++++++++++++++----- right/src/test_suite/tests/test_doubletap.c | 4 +- right/src/test_suite/tests/test_link.c | 120 ++++++ right/src/test_suite/tests/tests.c | 17 + right/src/test_suite/tests/tests.h | 12 + shared/uart_parser.c | 60 +-- shared/uart_parser.h | 2 + 19 files changed, 781 insertions(+), 163 deletions(-) create mode 100644 right/src/test_suite/test_statistics.c create mode 100644 right/src/test_suite/test_statistics.h create mode 100644 right/src/test_suite/tests/test_link.c diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index ec7860df1..cf5ba7655 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -206,7 +206,7 @@ static void logFrameBytes(const uint8_t* data, uint16_t len) { bool lineFull = n < 0 || pos + n >= sizeof(line) - 1; if (lineFull) { line[pos] = '\0'; - LogU(" %s\n", line); + LogWrn(" %s\n", line); pos = 0; if (++lines >= FRAME_DUMP_MAX_LINES) { break; @@ -216,7 +216,7 @@ static void logFrameBytes(const uint8_t* data, uint16_t len) { pos += n; } if (pos > 0) { - LogU(" %s%s\n", line, shown < len ? "..." : ""); + LogWrn(" %s%s\n", line, shown < len ? "..." : ""); } } @@ -245,7 +245,7 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ } else if (waiting) { stats.ackStale++; if (stats.ackStale == 1) { - LogU("Uart: ack watermark mismatch\n"); + LogWrn("Uart: ack watermark mismatch\n"); } } else { stats.ackWhileIdle++; @@ -288,7 +288,7 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ uartState->invalidMessagesCounter++; const char *out1, *out2; Messenger_GetMessageDescription(uartState->rxBuffer, 0, &out1, &out2); - LogUO("Crc-invalid UART message received! %s %s\n", out1, out2 == NULL ? "" : out2); + LogWrn("Crc-invalid UART message received! %s %s\n", out1, out2 == NULL ? "" : out2); logFrameBytes(uartState->rxBuffer, uartState->parser.rxPosition); setRxState(uartState, UartRxState_Nack); @@ -319,7 +319,7 @@ int UartBridge_SendMessage(message_t* msg) { int err; err = k_sem_take(&uartState->txBufferBusy, K_MSEC(UART_FOREVER_TIMEOUT)); if (err != 0) { - LogUOS("Uart: failed to take txBufferBusy semaphore.\n"); + LogWrn("Uart: failed to take txBufferBusy semaphore.\n"); } // Mark the exchange outstanding before waking, so the control thread's sleep gate @@ -385,11 +385,11 @@ static void resend(uart_state_t *uartState, bool wakePeer) { } if (uartState->resendTries++ >= UART_RESEND_COUNT) { stats.giveUps++; - LogU("Repeatedly failed to send a message! "); + LogErr("Repeatedly failed to send a message! "); for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { - LogU("%i ", uartState->parser.txBuffer[i]); + LogErr("%i ", uartState->parser.txBuffer[i]); } - LogU("\n"); + LogErr("\n"); uartState->resendTries = 0; uartState->txState = UartTxState_Idle; @@ -484,7 +484,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { } if (uartState->txState == UartTxState_Resend) { - LogU("Uart: received Nack, resending\n"); + LogWrn("Uart: received Nack, resending\n"); resend(uartState, false); } @@ -492,7 +492,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { uint32_t resendDelay = UART_RESEND_DELAY + UART_FRAME_WIRE_TIME_MS(uartState->parser.txPosition); bool ackOverdue = uartState->txState == UartTxState_WaitingForAck && currentTime >= uartState->lastMessageSentTime + resendDelay; if (ackOverdue) { - LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); + LogWrn("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); resend(uartState, true); } diff --git a/device/src/messenger.c b/device/src/messenger.c index 9431d96a0..3d2d9b78d 100644 --- a/device/src/messenger.c +++ b/device/src/messenger.c @@ -1,4 +1,5 @@ #include "messenger.h" +#include "test_suite/test_hooks.h" #include "bt_conn.h" #include "connections.h" #include "device.h" @@ -397,6 +398,9 @@ static void handleCommand(device_id_t src, const uint8_t* data, uint16_t len) { case MessengerCommand_Reboot: Reboot(false); break; + case MessengerCommand_StartTest: + TestHooks_StartLinkTest(data[MessageOffset_MsgId1+2]); + break; default: printk("Unknown command: %d\n", command); break; diff --git a/device/src/messenger.h b/device/src/messenger.h index 9f755ddb7..340fb0b29 100644 --- a/device/src/messenger.h +++ b/device/src/messenger.h @@ -29,6 +29,7 @@ typedef enum { MessengerCommand_Reboot = 0, + MessengerCommand_StartTest = 1, MessengerCommand_Count, } messenger_command_t; diff --git a/right/src/macros/debug_commands.c b/right/src/macros/debug_commands.c index 43cb9b4f2..1490aadd9 100644 --- a/right/src/macros/debug_commands.c +++ b/right/src/macros/debug_commands.c @@ -149,9 +149,53 @@ macro_result_t Macros_ProcessStatsActiveMacrosCommand() // provided by the patched c2usb (usb/df/mac_diag.hpp) extern void c2usb_diag_dump(void); +#ifdef __ZEPHYR__ +#include +#include + +extern k_tid_t Main_ThreadId; + +#define MAIN_DUMP_SCAN_WORDS 160 +#define MAIN_DUMP_MAX_ADDRS 10 + +// Where the main thread sits: its state, the pc/lr of its saved frame, and the thumb return +// addresses found on its stack - resolve them with addr2line against zephyr.elf. A blocked +// main shows up as a wait inside some caller; an idle one as the wait in scheduleNextRun. +static void dumpMainThread(void) { + const struct k_thread *thread = Main_ThreadId; + char state[24]; + const uint32_t *sp = (const uint32_t *)thread->callee_saved.psp; + uint32_t stackStart = thread->stack_info.start; + uint32_t stackEnd = stackStart + thread->stack_info.size; + bool spValid = (uint32_t)sp >= stackStart && (uint32_t)sp + 32 <= stackEnd; + + k_thread_state_str(Main_ThreadId, state, sizeof(state)); + LogTo(DEVICE_ID, LogTarget_Uart | LogTarget_ErrorBuffer, "Main thread [%s] pc=%x lr=%x\n", + state, spValid ? sp[6] : 0, spValid ? sp[5] : 0); + + if (spValid) { + char line[128]; + int at = snprintf(line, sizeof(line), " stack:"); + uint8_t found = 0; + for (uint16_t i = 8; i < MAIN_DUMP_SCAN_WORDS && (uint32_t)&sp[i] < stackEnd && found < MAIN_DUMP_MAX_ADDRS; i++) { + uint32_t word = sp[i]; + bool looksLikeReturn = (word & 1) && word > 0x1000 && word < 0x100000; + if (looksLikeReturn) { + at += snprintf(line + at, sizeof(line) - at, " %x", word); + found++; + } + } + LogTo(DEVICE_ID, LogTarget_Uart | LogTarget_ErrorBuffer, "%s\n", line); + } +} +#endif + void Macros_RecoverDiagnostics(void) { Macros_ProcessClearStatusCommand(true); +#ifdef __ZEPHYR__ + dumpMainThread(); +#endif c2usb_diag_dump(); Hid_DumpTransportState(); #if DEVICE_IS_KEYBOARD && defined(__ZEPHYR__) diff --git a/right/src/test_suite/CLAUDE.md b/right/src/test_suite/CLAUDE.md index 9bedf5e80..02f44025c 100644 --- a/right/src/test_suite/CLAUDE.md +++ b/right/src/test_suite/CLAUDE.md @@ -50,13 +50,25 @@ This matters when you want a base-layer macro to run while a layer is held (e.g. ## Key Timing - **Debouncing**: 50ms on press and another 50ms on release. -- Always `TEST_DELAY__(50)` (or more) after a press/release to let the key register. +- Delays run on one schedule from the test's start (start + all delays so far), not from when + each delay began - so ticks spent on other actions do not add up. A delay therefore separates + two actions by its length *minus* the ticks of the actions between them: a key held or released + across exactly `TEST_DELAY__(50)` can land inside the debounce window. Use `TEST_DELAY__(60)` + where a phase has to clear debouncing. ## Key Selection - **Always use right-half keys**: j, k, l, ;, p, o, i, u, m, n, h, y, 7, 8, 9, 0, etc. - Never use left-half keys (a, s, d, f, q, w, e, r, etc.) — the test rig only drives the right half. +### Exception: link tests + +A test with a nonzero `linkTestId` is a *link test* and may use left-half keys. The left half +runs the same script and presses those keys itself, so they genuinely traverse the bridge; +the right half skips them locally (`skipLocally` in `test_input_machine.c`). See +`tests/test_link.c`. Such tests must space input actions by debounce + margin, not the usual +50ms, because both halves run independent timelines. + ## Macro Formatting For `TEST_SET_MACRO` / `TEST_SET_LAYER_MACRO`, use multiline format with `\n`: @@ -100,4 +112,7 @@ TEST_SET_MACRO("j", "ifShortcut k final tapKey n\n holdKey j") - `LOG_VERBOSE(fmt, ...)` is conditional. - `TEST_EXPECT___________MAYBE` only logs in verbose mode. - Failures are always logged immediately via `LOG_FAILURE(fmt, ...)`, which prints a separator before the first failure of a test; failed tests are auto-rerun with verbose enabled. +- Tests with `repeatCount > 1` are never verbose, even when run as a single test, and never auto-rerun: every repetition runs, a repetition with any + failure counts as one failed repetition, and the verdict line reports `N passed, M failed`. +- The left half (link tests) logs no test actions; its log stays reserved for bridge diagnostics. - Reset `TestSuite_Verbose = false` after a verbose rerun. diff --git a/right/src/test_suite/CMakeLists.txt b/right/src/test_suite/CMakeLists.txt index 3e83bb097..e09bd82d1 100644 --- a/right/src/test_suite/CMakeLists.txt +++ b/right/src/test_suite/CMakeLists.txt @@ -1,5 +1,6 @@ target_sources(${PROJECT_NAME} PRIVATE test_suite.c + test_statistics.c test_input_machine.c test_output_machine.c tests/tests.c @@ -21,4 +22,5 @@ target_sources(${PROJECT_NAME} PRIVATE tests/test_transport.c tests/test_tapkeyseq.c tests/test_fail.c + tests/test_link.c ) diff --git a/right/src/test_suite/test_actions.h b/right/src/test_suite/test_actions.h index 870782a53..f5d265cee 100644 --- a/right/src/test_suite/test_actions.h +++ b/right/src/test_suite/test_actions.h @@ -123,6 +123,11 @@ typedef struct { typedef struct { const char *name; const test_action_t *actions; + // Nonzero marks a link test: the left half runs the same script and produces its own key presses physically. + uint8_t linkTestId; + // How many times to run the action list. 0 and 1 both mean once. Lets a short cycle be + // soaked without spending flash on a long static array. + uint16_t repeatCount; } test_t; #endif diff --git a/right/src/test_suite/test_hooks.h b/right/src/test_suite/test_hooks.h index 504cda886..651bee3ae 100644 --- a/right/src/test_suite/test_hooks.h +++ b/right/src/test_suite/test_hooks.h @@ -14,4 +14,8 @@ void TestHooks_CaptureReport(const hid_keyboard_report_t *report); // Called each update cycle to advance the test state machine void TestHooks_Tick(void); +// Joins a link test the peer has started, or stops the running one when given 0. Called from +// the bridge's receive path, so it must only flip state. +void TestHooks_StartLinkTest(uint8_t linkTestId); + #endif diff --git a/right/src/test_suite/test_input_machine.c b/right/src/test_suite/test_input_machine.c index 1598f1ac4..16e57152d 100644 --- a/right/src/test_suite/test_input_machine.c +++ b/right/src/test_suite/test_input_machine.c @@ -1,5 +1,6 @@ #include "test_input_machine.h" #include "test_hooks.h" +#include "device.h" #include "test_suite.h" #include "macros/keyid_parser.h" #include "macros/shortcut_parser.h" @@ -7,6 +8,7 @@ #include "str_utils.h" #include "key_action.h" #include "key_states.h" +#include "slot.h" #include "keymap.h" #include "layer.h" #include "timer.h" @@ -16,7 +18,9 @@ #include "utils.h" #include "usb_report_updater.h" -#define LOG_VERBOSE(fmt, ...) do { if (TestSuite_Verbose) LogU(fmt, ##__VA_ARGS__); } while(0) +// The left half only produces keys for a link test and logs none of its actions - its log +// is reserved for the bridge's own diagnostics. +#define LOG_VERBOSE(fmt, ...) do { if (TestSuite_Verbose && !DEVICE_IS_UHK80_LEFT) LogU(fmt, ##__VA_ARGS__); } while(0) #define TEST_TIMEOUT_MS 100 @@ -30,10 +34,15 @@ static bool endReached = false; // Delay state static bool inDelay = false; -static uint32_t delayStartTime = 0; + +// The test's schedule: its start plus every delay so far. A delay waits until this point +// rather than for its length from whenever it happened to begin, so the ticks spent on other +// actions don't accumulate into drift - which matters in link tests, where both halves run +// the script and their timelines must stay in step. +static uint32_t currentTestTime = 0; // Key ID parsing: convert string like "u" or "leftShift" to slot + keyId -static bool parseKeyId(const char *keyIdStr, uint8_t *slotId, uint8_t *keyId) { +bool TestInput_ParseKeyId(const char *keyIdStr, uint8_t *slotId, uint8_t *keyId) { if (keyIdStr == NULL) { return false; } @@ -122,7 +131,27 @@ void InputMachine_Start(const test_t *test) { endReached = false; endReachedTime = 0; inDelay = false; - delayStartTime = 0; + currentTestTime = Timer_GetCurrentTime(); +} + +// Only the half that runs the user logic consumes this event. Setting it on the left leaves it +// permanently pending, which user_logic reports on every pass - enough to flood the left's log +// buffer and make its diagnostics unreadable. +static void notifyStateMatrixChanged(void) { + bool consumedLocally = !DEVICE_IS_UHK80_LEFT; + + if (consumedLocally) { + EventVector_Set(EventVector_StateMatrix); + EventVector_WakeMain(); + } +} + +// In a link test both halves run the same script and each presses only the keys it physically +// owns, so the other half's presses are its job, not ours. +static bool isForeignSlot(uint8_t slotId) { + return InputMachine_CurrentTest != NULL + && InputMachine_CurrentTest->linkTestId != 0 + && slotId != CURRENT_SLOT_ID; } void InputMachine_Tick(void) { @@ -144,11 +173,15 @@ void InputMachine_Tick(void) { switch (action->type) { case TestAction_Press: { uint8_t slotId, keyId; - if (parseKeyId(action->keyId, &slotId, &keyId)) { + if (TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { + if (isForeignSlot(slotId)) { + LOG_VERBOSE("[TEST] > Press [%s] - other half's job\n", action->keyId); + InputMachine_ActionIndex++; + return; + } KeyStates[slotId][keyId].hardwareSwitchState = true; LOG_VERBOSE("[TEST] > Press [%s]\n", action->keyId); - EventVector_Set(EventVector_StateMatrix); - EventVector_WakeMain(); + notifyStateMatrixChanged(); } else { LOG_FAILURE("[TEST] FAIL: Press [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; @@ -160,11 +193,15 @@ void InputMachine_Tick(void) { case TestAction_Release: { uint8_t slotId, keyId; - if (parseKeyId(action->keyId, &slotId, &keyId)) { + if (TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { + if (isForeignSlot(slotId)) { + LOG_VERBOSE("[TEST] > Release [%s] - other half's job\n", action->keyId); + InputMachine_ActionIndex++; + return; + } KeyStates[slotId][keyId].hardwareSwitchState = false; LOG_VERBOSE("[TEST] > Release [%s]\n", action->keyId); - EventVector_Set(EventVector_StateMatrix); - EventVector_WakeMain(); + notifyStateMatrixChanged(); } else { LOG_FAILURE("[TEST] FAIL: Release [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; @@ -174,24 +211,24 @@ void InputMachine_Tick(void) { return; } - case TestAction_Delay: + case TestAction_Delay: { if (!inDelay) { inDelay = true; - delayStartTime = Timer_GetCurrentTime(); - return; - } else { - if (Timer_GetElapsedTime(&delayStartTime) >= action->delayMs) { - LOG_VERBOSE("[TEST] > Delay %dms\n", action->delayMs); - inDelay = false; - InputMachine_ActionIndex++; - break; - } - return; + currentTestTime += action->delayMs; + } + bool due = (int32_t)(Timer_GetCurrentTime() - currentTestTime) >= 0; + if (due) { + LOG_VERBOSE("[TEST] > Delay %dms\n", action->delayMs); + inDelay = false; + InputMachine_ActionIndex++; + break; } + return; + } case TestAction_SetAction: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetAction [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; @@ -216,7 +253,7 @@ void InputMachine_Tick(void) { case TestAction_SetMacro: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetMacro [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; @@ -237,7 +274,7 @@ void InputMachine_Tick(void) { case TestAction_SetLayerHold: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetLayerHold [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; @@ -260,7 +297,7 @@ void InputMachine_Tick(void) { case TestAction_SetLayerAction: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetLayerAction [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; @@ -285,7 +322,7 @@ void InputMachine_Tick(void) { case TestAction_SetSecondaryRole: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetSecondaryRole [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; @@ -310,7 +347,7 @@ void InputMachine_Tick(void) { case TestAction_SetGenericAction: { uint8_t slotId, keyId; - if (!parseKeyId(action->keyId, &slotId, &keyId)) { + if (!TestInput_ParseKeyId(action->keyId, &slotId, &keyId)) { LOG_FAILURE("[TEST] FAIL: SetGenericAction [%s] - invalid key\n", action->keyId); InputMachine_Failed = true; return; diff --git a/right/src/test_suite/test_input_machine.h b/right/src/test_suite/test_input_machine.h index 781db3d9d..edd16725e 100644 --- a/right/src/test_suite/test_input_machine.h +++ b/right/src/test_suite/test_input_machine.h @@ -14,6 +14,10 @@ extern bool InputMachine_TimedOut; // Initialize the input machine for a new test void InputMachine_Start(const test_t *test); +// Resolves a test-script key id string to slot/key. Shared with the left half's link-test +// producer, so both sides read the same script identically. +bool TestInput_ParseKeyId(const char *keyIdStr, uint8_t *slotId, uint8_t *keyId); + // Process one tick - called from scanner // Processes Press, Release, Delay, SetAction, CheckNow // Skips (advances past) Expect diff --git a/right/src/test_suite/test_statistics.c b/right/src/test_suite/test_statistics.c new file mode 100644 index 000000000..a33731f2c --- /dev/null +++ b/right/src/test_suite/test_statistics.c @@ -0,0 +1,106 @@ +#include "test_statistics.h" + +// Repeated tests run in this suite pass, how many of them failed, and their p-values +// combined (product and -ln of the product) for Fisher's method. +static uint16_t statisticalCount = 0; +static uint16_t statisticalFailedCount = 0; +static float statisticalPProduct = 1.0f; +static float statisticalNegLogP = 0.0f; + +// -ln(1 - TEST_SPURIOUS_FAILURE_RATE) by its series r + r^2/2 + r^3/3 + ..., folded at compile +// time; five terms are accurate to ~1e-5 at 20%. +#define TEST_R TEST_SPURIOUS_FAILURE_RATE +#define TEST_SPURIOUS_FAILURE_NEG_LOG \ + (TEST_R + TEST_R*TEST_R/2 + TEST_R*TEST_R*TEST_R/3 + TEST_R*TEST_R*TEST_R*TEST_R/4 \ + + TEST_R*TEST_R*TEST_R*TEST_R*TEST_R/5) + +// Confidence that `failed` failures out of `trials` are more than chance, each trial failing +// spuriously with probability `rate`: the probability of seeing fewer, P(X < failed) for +// X ~ Binomial(trials, rate). +static float confidenceSomethingIsWrong(uint16_t failed, uint16_t trials, float rate) { + float pExactly = 1.0f; + for (uint16_t i = 0; i < trials; i++) { + pExactly *= 1.0f - rate; + } + float pFewer = 0.0f; + for (uint16_t k = 0; k < failed && k < trials; k++) { + pFewer += pExactly; + pExactly *= (float)(trials - k) / (float)(k + 1) * rate / (1.0f - rate); + } + return pFewer; +} + +// A repetition's own spurious rate, such that the whole test fails at TEST_SPURIOUS_FAILURE_RATE: +// 1 - (1 - rate)^(1/n), to first order in 1/n. Not via a pow approximation - the result is the +// small difference from 1, which a few percent of error in the power would swamp. +static float repetitionFailureRate(uint16_t repetitions) { + return TEST_SPURIOUS_FAILURE_NEG_LOG / repetitions; +} + +// Natural log without libm: the float's exponent, plus 2 * atanh((m - 1) / (m + 1)) for the +// mantissa m in [0.5, 1), whose series is accurate to ~1e-5 within four terms. +static float naturalLog(float x) { + union { + float f; + uint32_t i; + } u = { x }; + int32_t exponent = (int32_t)((u.i >> 23) & 0xff) - 126; + u.i = (u.i & 0x807fffff) | (126u << 23); + float t = (u.f - 1.0f) / (u.f + 1.0f); + float t2 = t * t; + float mantissaLog = 2.0f * t * (1.0f + t2 * (1.0f / 3 + t2 * (1.0f / 5 + t2 * (1.0f / 7)))); + return exponent * 0.6931472f + mantissaLog; +} + +// Fisher's method: how likely a product of `count` healthy p-values is to come out as small +// as `product`, i.e. product * sum_{k < count} (-ln product)^k / k!, and one minus that. +static float combinedConfidence(float product, float negLogProduct, uint16_t count) { + float tail = 0.0f; + float term = 1.0f; + for (uint16_t k = 0; k < count; k++) { + tail += term; + term *= negLogProduct / (float)(k + 1); + } + return 1.0f - product * tail; +} + +unsigned TestStatistics_AsPercent(float probability) { + return (unsigned)(probability * 100.0f + 0.5f); +} + +void TestStatistics_Reset(void) { + statisticalCount = 0; + statisticalFailedCount = 0; + statisticalPProduct = 1.0f; + statisticalNegLogP = 0.0f; +} + +float TestStatistics_RepeatedTestConfidence(uint16_t failed, uint16_t repetitions) { + return confidenceSomethingIsWrong(failed, repetitions, repetitionFailureRate(repetitions)); +} + +void TestStatistics_AddRepeatedTest(float confidence, bool failed) { + // Floored, so a near-certain failure does not underflow the product to nothing. + float pValue = 1.0f - confidence; + if (pValue < 1e-30f) { + pValue = 1e-30f; + } + statisticalCount++; + statisticalPProduct *= pValue; + statisticalNegLogP -= naturalLog(pValue); + if (failed) { + statisticalFailedCount++; + } +} + +uint16_t TestStatistics_RepeatedTestCount(void) { + return statisticalCount; +} + +uint16_t TestStatistics_FailedRepeatedTestCount(void) { + return statisticalFailedCount; +} + +float TestStatistics_SuiteConfidence(void) { + return combinedConfidence(statisticalPProduct, statisticalNegLogP, statisticalCount); +} diff --git a/right/src/test_suite/test_statistics.h b/right/src/test_suite/test_statistics.h new file mode 100644 index 000000000..dcbf97f94 --- /dev/null +++ b/right/src/test_suite/test_statistics.h @@ -0,0 +1,29 @@ +#ifndef __TEST_STATISTICS_H__ +#define __TEST_STATISTICS_H__ + +// Includes: + + #include + #include + +// Macros: + + // How often a healthy repeated test is allowed to fail, over the whole test: its timings are + // set against random stress, so some failures are expected and only their number is evidence. + #define TEST_SPURIOUS_FAILURE_RATE 0.2f + +// Functions: + + // Confidence that `failed` failed repetitions out of `repetitions` are more than chance. + float TestStatistics_RepeatedTestConfidence(uint16_t failed, uint16_t repetitions); + + // The repeated tests of a suite run, combined by Fisher's method. + void TestStatistics_Reset(void); + void TestStatistics_AddRepeatedTest(float confidence, bool failed); + uint16_t TestStatistics_RepeatedTestCount(void); + uint16_t TestStatistics_FailedRepeatedTestCount(void); + float TestStatistics_SuiteConfidence(void); + + unsigned TestStatistics_AsPercent(float probability); + +#endif diff --git a/right/src/test_suite/test_suite.c b/right/src/test_suite/test_suite.c index 74f044757..7d31576f4 100644 --- a/right/src/test_suite/test_suite.c +++ b/right/src/test_suite/test_suite.c @@ -1,7 +1,10 @@ #include "test_suite.h" +#include "messenger.h" +#include "device.h" #include "test_hooks.h" #include "test_actions.h" #include "test_input_machine.h" +#include "test_statistics.h" #include "test_output_machine.h" #include "tests/tests.h" #include "logger.h" @@ -13,6 +16,17 @@ #include "mouse_controller.h" #include "layer_stack.h" #include "postponer.h" +#include "slot.h" +#include "key_states.h" +#include "module.h" +#include + +#if defined(__ZEPHYR__) && DEVICE_IS_UHK80_LEFT +#include "link_protocol.h" +#include "connections.h" +#include "bool_array_converter.h" +#include +#endif #if defined(__ZEPHYR__) && DEVICE_IS_KEYBOARD #include "keyboard/battery_unloaded_calculator.h" @@ -42,8 +56,6 @@ static bool singleTestMode = false; // Rerun state for failed tests static bool isRerunning = false; -static uint16_t rerunModuleIndex = 0; -static uint16_t rerunTestIndex = 0; // Inter-test delay state static bool inInterTestDelay = false; @@ -80,7 +92,23 @@ static bool advanceToNextTest(void) { extern hid_keyboard_report_t *ActiveKeyboardReport; +// Repeats are re-runs of the whole test, not a wrap of the action index, so that each pass +// re-sends StartTest to the left half. Both halves therefore restart their timelines together +// every pass; wrapping the index instead let their independent delay timers drift apart over +// hundreds of steps, until a left change landed after a right one scripted later. +static const test_t *repeatingTest = NULL; +static uint16_t repeatsLeft = 0; +static uint16_t repetitionsPassed = 0; +static uint16_t repetitionsFailed = 0; + static void startTest(const test_t *test, const test_module_t *module) { + if (test != repeatingTest) { + repeatingTest = test; + repeatsLeft = test->repeatCount > 0 ? test->repeatCount - 1 : 0; + repetitionsPassed = 0; + repetitionsFailed = 0; + } + Macros_StopAllMacros(); ConfigManager_ResetConfiguration(false, false); LayerStack_Reset(); @@ -92,6 +120,10 @@ static void startTest(const test_t *test, const test_module_t *module) { TestSuite_LogSeparatorOnce(); LogU("[TEST] Running: %s/%s\n", module->name, test->name); } + if (DEVICE_IS_UHK80_RIGHT && test->linkTestId != 0) { + Messenger_Send2(DeviceId_Uhk80_Left, MessageId_Command, MessengerCommand_StartTest, &test->linkTestId, sizeof(test->linkTestId)); + } + InputMachine_Start(test); OutputMachine_Start(test); OutputMachine_OnReportChange(ActiveKeyboardReport); @@ -104,127 +136,296 @@ void TestHooks_CaptureReport(const hid_keyboard_report_t *report) { OutputMachine_OnReportChange(report); } -void TestHooks_Tick(void) { - if (!TestHooks_Active) { - return; +// True once the inter-test pause has elapsed and the next test has been started. +static bool waitOutInterTestDelay(void) { + if (Timer_GetElapsedTime(&interTestDelayStart) < INTER_TEST_DELAY___MS) { + return false; } - // Handle inter-test delay - if (inInterTestDelay) { - if (Timer_GetElapsedTime(&interTestDelayStart) >= INTER_TEST_DELAY___MS) { - inInterTestDelay = false; - const test_t *nextTest = getCurrentTest(); - const test_module_t *module = AllTestModules[currentModuleIndex]; - startTest(nextTest, module); + inInterTestDelay = false; + const test_t *nextTest = getCurrentTest(); + const test_module_t *module = AllTestModules[currentModuleIndex]; + startTest(nextTest, module); + return true; +} + +#if defined(__ZEPHYR__) && DEVICE_IS_UHK80_LEFT +// The left half's whole contribution to a link test: hand the keys the shared interpreter has +// just pressed to the right half, in place of what scanAllKeys would have sent. +// +// On change only, exactly as scanAllKeys does. Sending every tick would make the sender block +// on txBufferBusy continuously, which both floods the link and hides the thing under test - +// the stall only matters when it delays the *next* state change. +// +// Pinned to the UART connection rather than left to determineChannel: with BLE to the right +// also up the default route can carry this over NUS instead, and the test would then be +// exercising the wrong link. +static void publishOwnKeyStates(void) { + static uint8_t previous[MAX_KEY_COUNT_PER_MODULE/8+1]; + uint8_t length = MAX_KEY_COUNT_PER_MODULE/8+1; + uint8_t bitmap[length]; + memset(bitmap, 0, length); + + for (uint8_t keyId = 0; keyId < MAX_KEY_COUNT_PER_MODULE; keyId++) { + if (KeyStates[CURRENT_SLOT_ID][keyId].hardwareSwitchState) { + BoolBitToBytes(true, keyId, bitmap); } - return; } - InputMachine_Tick(); + bool changed = memcmp(bitmap, previous, length) != 0; - // Check for completion or failure - bool inputDone = InputMachine_IsDone(); - bool outputDone = OutputMachine_IsDone(); - bool failed = InputMachine_Failed || OutputMachine_Failed; - bool timedOut = InputMachine_TimedOut && !outputDone; - bool macrosRunning = Macros_AnyMacroRunning(); - - // If input/output done but macros still running, wait for timeout - if (inputDone && outputDone && macrosRunning && !timedOut && !failed) { - return; + if (changed) { + memcpy(previous, bitmap, length); + Messenger_Send2Via(DeviceId_Uhk80_Right, ConnectionId_UartRight, + MessageId_SyncableProperty, SyncablePropertyId_LeftHalfKeyStates, bitmap, length); } +} + +// Set while the left half plays its part in a link test the right half is running. Otherwise +// the left half runs whatever suite it was asked to, like any other device. +static bool isLinkTestPeer = false; + +// StartTest arrives on the messenger's receive path, while the input machine is ticked by the +// key scanner. The right restarts the left just as the left finishes its previous run, so +// starting from the receive path raced the finish: the scanner, having just seen the old run +// end, switched the freshly started one off and the left sat out the repetition. The receive +// path only posts the id; the scanner thread does the starting. +static atomic_t pendingLinkTestId = ATOMIC_INIT(0); - if (inputDone && (outputDone || timedOut || failed)) { - const test_t *test = getCurrentTest(); - const test_module_t *module = AllTestModules[currentModuleIndex]; +static void startPendingLinkTest(void) { + uint8_t linkTestId = (uint8_t)atomic_set(&pendingLinkTestId, 0); - // On timeout, kill all running macros - if (timedOut) { - Macros_StopAllMacros(); + if (linkTestId != 0) { + const test_t *test = Tests_FindLinkTest(linkTestId); + bool known = test != NULL; + + if (known) { + InputMachine_Start(test); } + isLinkTestPeer = known; + } +} - if (failed || timedOut) { - if (isRerunning || singleTestMode) { - // Already rerunning with verbose (or single test mode), log final result - if (failed) { - LOG_FAILURE("[TEST] Finished: %s/%s - FAIL\n", module->name, test->name); - } else { - LOG_FAILURE("[TEST] Finished: %s/%s - TIMEOUT\n", module->name, test->name); - } - closeTestLog(); - failedCount++; - isRerunning = false; - TestSuite_Verbose = false; // Reset to non-verbose for remaining tests - - if (singleTestMode) { - goto finish; - } - - // Continue from where we left off - currentModuleIndex = rerunModuleIndex; - currentTestIndex = rerunTestIndex; - if (advanceToNextTest()) { - inInterTestDelay = true; - interTestDelayStart = Timer_GetCurrentTime(); - } else { - goto finish; - } - } else { - // First failure - log and save position for rerun with verbose - if (failed) { - LOG_FAILURE("[TEST] Finished: %s/%s - FAIL (rerunning verbose)\n", module->name, test->name); - } else { - LOG_FAILURE("[TEST] Finished: %s/%s - TIMEOUT (rerunning verbose)\n", module->name, test->name); - } - rerunModuleIndex = currentModuleIndex; - rerunTestIndex = currentTestIndex; - isRerunning = true; - TestSuite_Verbose = true; - - inInterTestDelay = true; - interTestDelayStart = Timer_GetCurrentTime(); - } - } else { - if (isRerunning) { - // Failed in the first run, passed in the rerun - LogU("[TEST] Finished: %s/%s - PARTIAL (passed on rerun)\n", module->name, test->name); - partialCount++; - isRerunning = false; - TestSuite_Verbose = false; // Reset to non-verbose for remaining tests - } else { - LogU("[TEST] Finished: %s/%s - PASS\n", module->name, test->name); - passedCount++; - } - closeTestLog(); +// The left half has no USB reports to validate, so it runs the input machine only. +static void tickLinkTestPeer(void) { + startPendingLinkTest(); - if (singleTestMode) { - goto finish; - } + if (isLinkTestPeer) { + InputMachine_Tick(); + publishOwnKeyStates(); - // Move to next test - if (advanceToNextTest()) { - inInterTestDelay = true; - interTestDelayStart = Timer_GetCurrentTime(); - } else { - goto finish; - } + if (InputMachine_IsDone()) { + isLinkTestPeer = false; } } - return; -finish: + // Re-checked after clearing, so a StartTest landing in between keeps the scanner coming. + TestHooks_Active = isLinkTestPeer; + if (atomic_get(&pendingLinkTestId) != 0) { + TestHooks_Active = true; + } +} +#endif + +typedef enum { + TestOutcome_Running, + TestOutcome_Passed, + TestOutcome_Failed, + TestOutcome_TimedOut, +} test_outcome_t; + +// Whether the current test (or repetition) has ended, and how. With input and output both done +// but macros still running it waits for them: they end, or the input machine times out. +static test_outcome_t evaluateCurrentTest(void) { + bool inputDone = InputMachine_IsDone(); + bool outputDone = OutputMachine_IsDone(); + bool failed = InputMachine_Failed || OutputMachine_Failed; + bool timedOut = InputMachine_TimedOut && !outputDone; + bool waitingForMacros = outputDone && Macros_AnyMacroRunning() && !timedOut && !failed; + bool ended = inputDone && (outputDone || timedOut || failed) && !waitingForMacros; + + test_outcome_t outcome = TestOutcome_Running; + if (ended && failed) { + outcome = TestOutcome_Failed; + } else if (ended && timedOut) { + outcome = TestOutcome_TimedOut; + } else if (ended) { + outcome = TestOutcome_Passed; + } + return outcome; +} + +static void finishSuite(void) { Macros_StopAllMacros(); if (!separatorPrinted) { // Otherwise the last test has already closed its log with a separator LogU("[TEST] ----------------------\n"); } - LogU("[TEST] Complete: %d passed, %d partial, %d failed\n", passedCount, partialCount, failedCount); + LogU("[TEST] Complete:\n"); + LogU("[TEST] Discrete tests: %d passed, %d partial, %d failed\n", passedCount, partialCount, failedCount); + uint16_t repeated = TestStatistics_RepeatedTestCount(); + uint16_t repeatedFailed = TestStatistics_FailedRepeatedTestCount(); + uint16_t repeatedSucceeded = repeated - repeatedFailed; + if (repeatedFailed > 0) { + LogU("[TEST] Repeated tests: %u passed, %u failed, %u%% fail confidence\n", (unsigned)repeatedSucceeded, + (unsigned)repeatedFailed, TestStatistics_AsPercent(TestStatistics_SuiteConfidence())); + } else if (repeated > 0) { + LogU("[TEST] Repeated tests: %u passed, %u failed\n", (unsigned)repeatedSucceeded, (unsigned)repeatedFailed); + } + LogU("[TEST] ----------------------\n"); TestHooks_Active = false; ConfigManager_ResetConfiguration(false, false); LayerStack_Reset(); PostponerExtended_ResetPostponer(); } +// Closes the test's log and goes on: to the next test after the inter-test delay, or to the +// summary when there is none or only one test was asked for. +static void moveToNextTest(void) { + closeTestLog(); + bool anotherTest = !singleTestMode && advanceToNextTest(); + if (anotherTest) { + inInterTestDelay = true; + interTestDelayStart = Timer_GetCurrentTime(); + } else { + finishSuite(); + } +} + +static void concludeRepeatedTest(const test_t *test, const test_module_t *module) { + uint16_t repetitions = repetitionsPassed + repetitionsFailed; + bool anyFailed = repetitionsFailed > 0; + float confidence = TestStatistics_RepeatedTestConfidence(repetitionsFailed, repetitions); + + if (anyFailed) { + LogU("[TEST] Finished: %s/%s - FAIL (%u/%u failed, %u%% fail confidence)\n", module->name, test->name, + (unsigned)repetitionsFailed, (unsigned)repetitions, TestStatistics_AsPercent(confidence)); + } else { + LogU("[TEST] Finished: %s/%s - PASS\n", module->name, test->name); + } + TestStatistics_AddRepeatedTest(confidence, anyFailed); + repeatingTest = NULL; + moveToNextTest(); +} + +// A repeated test is a run of independent trials. Every repetition is played out, a failed +// one is counted rather than ending the run, and nothing is re-run verbosely: a rerun's pass +// would only blur the failure rate the repetitions exist to measure. +static void concludeRepetition(const test_t *test, const test_module_t *module, test_outcome_t outcome) { + if (outcome == TestOutcome_Passed) { + repetitionsPassed++; + } else { + repetitionsFailed++; + // A mismatch is logged by the output machine; a timeout would pass silently. + const test_action_t *pending = &test->actions[OutputMachine_ActionIndex]; + bool pendingIsExpect = pending->type == TestAction_Expect || pending->type == TestAction_CheckNow; + if (outcome == TestOutcome_TimedOut && pendingIsExpect) { + LOG_FAILURE("[TEST] < TIMEOUT: still expecting '%s'\n", pending->expectShortcuts); + } + } + + if (repeatsLeft > 0) { + repeatsLeft--; + startTest(test, module); + } else { + concludeRepeatedTest(test, module); + } +} + +static void endVerboseRerun(void) { + isRerunning = false; + TestSuite_Verbose = false; +} + +// A test's first failure: run it again, verbosely, to log what went wrong. +static void scheduleVerboseRerun(const test_t *test, const test_module_t *module, const char *failure) { + LOG_FAILURE("[TEST] Finished: %s/%s - %s (rerunning verbose)\n", module->name, test->name, failure); + isRerunning = true; + TestSuite_Verbose = true; + inInterTestDelay = true; + interTestDelayStart = Timer_GetCurrentTime(); +} + +static void concludeTest(const test_t *test, const test_module_t *module, test_outcome_t outcome) { + const char *failure = outcome == TestOutcome_Failed ? "FAIL" : "TIMEOUT"; + bool lastAttempt = isRerunning || singleTestMode; + + if (outcome == TestOutcome_Passed && isRerunning) { + LogU("[TEST] Finished: %s/%s - PARTIAL (passed on rerun)\n", module->name, test->name); + partialCount++; + endVerboseRerun(); + moveToNextTest(); + } else if (outcome == TestOutcome_Passed) { + LogU("[TEST] Finished: %s/%s - PASS\n", module->name, test->name); + passedCount++; + moveToNextTest(); + } else if (lastAttempt) { + LOG_FAILURE("[TEST] Finished: %s/%s - %s\n", module->name, test->name, failure); + failedCount++; + endVerboseRerun(); + moveToNextTest(); + } else { + scheduleVerboseRerun(test, module, failure); + } +} + +// One tick of the suite: waits out the gap between tests, or drives the current test and, +// once it has ended, concludes it. +static void stepSuite(void) { + if (inInterTestDelay) { + waitOutInterTestDelay(); + } else { + InputMachine_Tick(); + test_outcome_t outcome = evaluateCurrentTest(); + + if (outcome != TestOutcome_Running) { + const test_t *test = getCurrentTest(); + const test_module_t *module = AllTestModules[currentModuleIndex]; + bool timedOut = InputMachine_TimedOut && !OutputMachine_IsDone(); + + if (timedOut) { + Macros_StopAllMacros(); + } + if (test->repeatCount > 1) { + concludeRepetition(test, module, outcome); + } else { + concludeTest(test, module, outcome); + } + } + } +} + +// Routes to whichever side of a test this device is responsible for. In a link test the right +// half owns the suite - sequencing, expectations, verdicts - while the left only produces keys. +void TestHooks_Tick(void) { + if (!TestHooks_Active) { + return; + } + +#if defined(__ZEPHYR__) && DEVICE_IS_UHK80_LEFT + if (isLinkTestPeer || atomic_get(&pendingLinkTestId) != 0) { + tickLinkTestPeer(); + } else { + stepSuite(); + } +#else + stepSuite(); +#endif +} + +// Entry point for the StartTest bridge command. Resolving and switching happens here rather +// than in the messenger, which should not know what a test is. A zero or unknown id stops +// whatever was running. +void TestHooks_StartLinkTest(uint8_t linkTestId) { +#if defined(__ZEPHYR__) && DEVICE_IS_UHK80_LEFT + atomic_set(&pendingLinkTestId, linkTestId); + TestHooks_Active = true; +#else + (void)linkTestId; +#endif +} + + void TestSuite_Init(void) { TestHooks_Active = false; } @@ -235,6 +436,7 @@ uint8_t TestSuite_RunAll(void) { passedCount = 0; partialCount = 0; failedCount = 0; + TestStatistics_Reset(); inInterTestDelay = false; isRerunning = false; singleTestMode = false; @@ -287,16 +489,19 @@ uint8_t TestSuite_RunSingle(const char *moduleStart, const char *moduleEnd, cons const test_t *test = &module->tests[ti]; if (!streq(testStart, testEnd, test->name)) continue; - // Found it - run with verbose logging + // Found it - run with verbose logging, unless it is a repeated test: those run + // hundreds of repetitions, so they log as in the full suite whichever way they are + // started. currentModuleIndex = mi; currentTestIndex = ti; passedCount = 0; partialCount = 0; failedCount = 0; + TestStatistics_Reset(); inInterTestDelay = false; isRerunning = false; singleTestMode = true; - TestSuite_Verbose = true; // Always verbose for single test + TestSuite_Verbose = test->repeatCount <= 1; LogU("[TEST] Running single test: %s/%s\n", module->name, test->name); startTest(test, module); @@ -324,6 +529,7 @@ static uint8_t TestSuite_RunModule(const char *moduleStart, const char *moduleEn passedCount = 0; partialCount = 0; failedCount = 0; + TestStatistics_Reset(); inInterTestDelay = false; isRerunning = false; singleTestMode = false; diff --git a/right/src/test_suite/tests/test_doubletap.c b/right/src/test_suite/tests/test_doubletap.c index 6276296f6..ce8850ef4 100644 --- a/right/src/test_suite/tests/test_doubletap.c +++ b/right/src/test_suite/tests/test_doubletap.c @@ -196,11 +196,11 @@ static const test_action_t other_key_release_breaks_doubletap[] = { TEST_EXPECT__________("i"), TEST_PRESS______("u"), TEST_EXPECT__________("u i"), - TEST_DELAY__(50), + TEST_DELAY__(60), TEST_RELEASE__U("u"), TEST_EXPECT__________("i"), TEST_RELEASE__U("i"), - TEST_DELAY__(50), + TEST_DELAY__(60), TEST_EXPECT__________(""), TEST_PRESS______("u"), TEST_RELEASE__U("u"), diff --git a/right/src/test_suite/tests/test_link.c b/right/src/test_suite/tests/test_link.c new file mode 100644 index 000000000..19ab3c5c3 --- /dev/null +++ b/right/src/test_suite/tests/test_link.c @@ -0,0 +1,120 @@ +#include "tests.h" +#include "slot.h" +#include "module.h" +#include "uart_defs.h" +#include "uart_parser.h" +#include "test_suite/test_statistics.h" + +// Tests that the left-right bridge recovers from a stressed link without losing or reordering +// key events. Both halves run the script; each presses only the keys it owns, so what the +// right half validates has actually crossed the wire. +// +// The failure mode under test is the left half's scanner stalling: its sender blocks until a +// frame is acked, so lost acks delay the *next* state change. + +// What one retry costs the sender: the ack budget plus the frame's own time on the wire, +// which the bridge charges separately. +#define LINK_FRAME_BYTES (3 + 2 + (MAX_KEY_COUNT_PER_MODULE/8+1) \ + + UART_LINK_START_END_BYTE_LEN + UART_LINK_CRC_BUF_LEN) +#define LINK_RETRY_COST_MS (UART_RESEND_DELAY + UART_FRAME_WIRE_TIME_MS(LINK_FRAME_BYTES)) + +// Retries the link is expected to absorb without the user noticing. +#define LINK_ABSORBED_RETRIES 2 + +// A key's changes are debounced (Cfg.DebounceTimePress/Release default): once a press or +// release commits, the key's next change waits the debounce out. Every phase - held, then +// released - must outlast it even when the change that opened it arrived late by the absorbed +// retries; otherwise the next change is postponed past a later key's and the report order +// breaks for reasons unrelated to the link. +#define LINK_DEBOUNCE_MS 50 +#define LINK_PHASE_MIN_MS (LINK_DEBOUNCE_MS + LINK_ABSORBED_RETRIES * LINK_RETRY_COST_MS) + +// Left-half keys are 'f' (81), 'g' (82), 'b' (89) and 'v' (88); 'j' (16) and 'k' are on the +// right. +#define LEFT_A "f" +#define LEFT_B "g" +#define LEFT_C "b" +#define LEFT_D "v" +#define RIGHT_A "j" +#define RIGHT_B "k" + +// Stress runs only between two quiet steps. The right half sends StartTest to the left just +// before the script begins, and the left trails the right by that message's latency, so +// without them the StartTest exchange itself could be stressed - a dropped ack resends it, +// and the left would restart its script a second time, out of step with the right. A quiet +// step covers the exchange: its ack loop measures well below it (at most ~14ms). +#define LINK_QUIET_MS 22 +#define LINK_STRESS_ON TEST_DELAY__(LINK_QUIET_MS), TEST_SET_BOOL(&UartStress_Active, true) +#define LINK_STRESS_OFF TEST_SET_BOOL(&UartStress_Active, false), TEST_DELAY__(LINK_QUIET_MS) + +// Probes the stall directly. A dropped ack never delays the frame it belongs to - that one +// already arrived - only the sender's *next* frame. So a probe is: left change L1, a second +// left change L2 shortly after, and a right change R that L2 must still beat. Retries on L1 +// hold L2 back until the sender is free again; L2's own corruption retries delay L2 itself. +// +// Measured on the stressed link: a timeout retry costs ~9.3ms, a nack retry ~3ms, and L2 +// lands ~6ms (+-2) after the sender frees up - after L1's 1 timeout at ~18ms, after 2 at +// ~28ms, so after 3 at ~37ms. Nacks being cheap, the boundary is in timeouts: R midway +// between two and three fails, per a model of the link with these costs, ~2% of probes +// whose L1 needed two timeouts and ~99% of those needing three. +// +// L2 goes as early as possible: any retry on L1 still holds it back, and its own corruption +// retries get the most room before R. +#define LINK_PROBE_L2_MS 4 +#define LINK_PROBE_R_MS 32 + +// Two probes, on disjoint keys, share a slot pair; every key changes once per two slots. A +// slot outlasts even a three-timeout L2, so a failing probe does not spill into the next. +#define LINK_SLOT_MS 40 +_Static_assert(LINK_PROBE_R_MS < LINK_SLOT_MS, "probe does not fit its slot"); +_Static_assert(2 * LINK_SLOT_MS >= LINK_PHASE_MIN_MS, + "probe keys are not held long enough to clear debouncing"); + +#define LINK_PROBE(L1, L1_EXPECT, L2, L2_EXPECT, R, R_EXPECT) \ + L1, TEST_EXPECT__________(L1_EXPECT), TEST_DELAY__(LINK_PROBE_L2_MS), \ + L2, TEST_EXPECT__________(L2_EXPECT), TEST_DELAY__(LINK_PROBE_R_MS - LINK_PROBE_L2_MS), \ + R, TEST_EXPECT__________(R_EXPECT), TEST_DELAY__(LINK_SLOT_MS - LINK_PROBE_R_MS) + +#define LINK_PROBES_PER_CYCLE 4 + +// Sized so a healthy run fails at TEST_SPURIOUS_FAILURE_RATE, the rate the suite's confidence +// figures assume: measured, a probe fails ~8e-4 of the time (the model above says ~4e-4, the +// excess unexplained), so 280 probes fail ~20% of runs while ~72% see a two-timeout streak. +#define LINK_PROBE_CYCLES 70 + +static const test_action_t test_link_probe[] = { + LINK_STRESS_ON, + TEST_SET_ACTION(LEFT_A, "f"), + TEST_SET_ACTION(LEFT_B, "g"), + TEST_SET_ACTION(LEFT_C, "b"), + TEST_SET_ACTION(LEFT_D, "v"), + TEST_SET_ACTION(RIGHT_A, "j"), + TEST_SET_ACTION(RIGHT_B, "k"), + + LINK_PROBE(TEST_PRESS______(LEFT_A), "f", TEST_PRESS______(LEFT_B), "f g", + TEST_PRESS______(RIGHT_A), "f g j"), + LINK_PROBE(TEST_PRESS______(LEFT_C), "f g j b", TEST_PRESS______(LEFT_D), "f g j b v", + TEST_PRESS______(RIGHT_B), "f g j b v k"), + LINK_PROBE(TEST_RELEASE__U(LEFT_A), "g j b v k", TEST_RELEASE__U(LEFT_B), "j b v k", + TEST_RELEASE__U(RIGHT_A), "b v k"), + LINK_PROBE(TEST_RELEASE__U(LEFT_C), "v k", TEST_RELEASE__U(LEFT_D), "k", + TEST_RELEASE__U(RIGHT_B), ""), + + LINK_STRESS_OFF, + TEST_END() +}; + +static const test_t link_tests[] = { + { + .name = "probe", + .actions = test_link_probe, + .linkTestId = LinkTestId_Probe, + .repeatCount = LINK_PROBE_CYCLES, + }, +}; + +const test_module_t TestModule_Link = { + .name = "Link", + .tests = link_tests, + .testCount = sizeof(link_tests) / sizeof(link_tests[0]) +}; diff --git a/right/src/test_suite/tests/tests.c b/right/src/test_suite/tests/tests.c index 10c1896b2..632fbe3fc 100644 --- a/right/src/test_suite/tests/tests.c +++ b/right/src/test_suite/tests/tests.c @@ -1,4 +1,5 @@ #include "tests.h" +#include // All test modules registered here const test_module_t * const AllTestModules[] = { @@ -21,6 +22,22 @@ const test_module_t * const AllTestModules[] = { &TestModule_TapKeySeq, // Always fails; uncomment to check that the framework reports failures. // &TestModule_Fail, + &TestModule_Link, }; const uint16_t AllTestModulesCount = sizeof(AllTestModules) / sizeof(AllTestModules[0]); + +const test_t* Tests_FindLinkTest(uint8_t linkTestId) { + if (linkTestId == LinkTestId_None) { + return NULL; + } + for (uint16_t moduleIndex = 0; moduleIndex < AllTestModulesCount; moduleIndex++) { + const test_module_t *module = AllTestModules[moduleIndex]; + for (uint16_t testIndex = 0; testIndex < module->testCount; testIndex++) { + if (module->tests[testIndex].linkTestId == linkTestId) { + return &module->tests[testIndex]; + } + } + } + return NULL; +} diff --git a/right/src/test_suite/tests/tests.h b/right/src/test_suite/tests/tests.h index 79efd8724..3ca11df6c 100644 --- a/right/src/test_suite/tests/tests.h +++ b/right/src/test_suite/tests/tests.h @@ -34,5 +34,17 @@ extern const test_module_t TestModule_Playtime; extern const test_module_t TestModule_Transport; extern const test_module_t TestModule_TapKeySeq; extern const test_module_t TestModule_Fail; +extern const test_module_t TestModule_Link; + +// Link test ids are the wire contract between the halves: the right half sends one in +// MessengerCommand_StartTest and the left looks the test up by it. Keep them stable. +typedef enum { + LinkTestId_None = 0, + LinkTestId_Probe = 3, +} link_test_id_t; + +// The test carrying this link test id, in any module, or NULL for LinkTestId_None or an +// unknown id. Both halves resolve an id to the same test, which is how they stay on one script. +const test_t* Tests_FindLinkTest(uint8_t linkTestId); #endif diff --git a/shared/uart_parser.c b/shared/uart_parser.c index cd42fe24e..4db67855b 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -19,6 +19,7 @@ #define DEBUG_STRESS_UART false #endif +// Do NOT change these - test_link.c statistics are calibrated against them. #define STRESS_RANDOM_RANGE 65536 #define STRESS_BYTE_FAULT_RECIPROCAL 512 #define STRESS_ACK_DROP_RECIPROCAL 16 @@ -36,17 +37,18 @@ static void appendRxByte(uart_parser_t *uartState, uint8_t byte) { uartState->rxBuffer[uartState->rxPosition++ - CRC_LEN] = byte; } else if (!uartState->rxTooLong) { uartState->rxTooLong = true; - LogU("Uart error: too long message, discarding [len %i: src %i, dst %i, msgId %i, propId %i]\n", + LogWrn("Uart error: too long message, discarding [len %i: src %i, dst %i, msgId %i, propId %i]\n", uartState->rxLength, uartState->rxBuffer[0], uartState->rxBuffer[1], uartState->rxBuffer[3], uartState->rxBuffer[4]); } } ATTR_UNUSED static uint16_t get_random(void) { - static uint16_t lfsr = 0xACE1; // Non-zero seed - uint16_t bit = ((lfsr >> 0) ^ (lfsr >> 2) ^ (lfsr >> 3) ^ (lfsr >> 5)) & 1; - lfsr = (lfsr >> 1) | (bit << 15); - return lfsr; + static uint32_t state = 0x2545F491; // Non-zero seed + state ^= state << 13; + state ^= state >> 17; + state ^= state << 5; + return (uint16_t)(state >> 16); } static bool isCrcValid(uart_parser_t *uartState, const uint8_t* buf, uint16_t len) { @@ -61,32 +63,40 @@ static bool isCrcValid(uart_parser_t *uartState, const uint8_t* buf, uint16_t le return CRC16_IsMessageValidExt(&msg); } -static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { -#if DEBUG_STRESS_UART - uint16_t r1 = get_random(); - uint8_t r2 = get_random(); - uint16_t r3 = get_random(); - - // Mutate byte - if (r1 < STRESS_BYTE_FAULT_THRESHOLD) { - LogU("UartStress: Oops!\n"); - byte = byte ^ r2; +bool UartStress_Active = DEBUG_STRESS_UART; + +// Returns true when the byte should be swallowed. Mutates `byte` in place otherwise. +static bool stressByte(uart_parser_t *uartState, uint8_t *byte) { + uint16_t corruptRoll = get_random(); + uint8_t corruptMask = get_random(); + uint16_t dropRoll = get_random(); + + if (corruptRoll < STRESS_BYTE_FAULT_THRESHOLD) { + LogWrn("UartStress: Oops!\n"); + *byte = *byte ^ corruptMask; } - // Or drop the byte - if (r3 < STRESS_BYTE_FAULT_THRESHOLD) { - LogU("UartStress: Oops lost!\n"); - return; + if (dropRoll < STRESS_BYTE_FAULT_THRESHOLD) { + LogWrn("UartStress: Oops lost!\n"); + return true; } // More dropped acks, more fun: CRC mutation alone never reaches the resend path. - bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Ack0 - || byte == UartControlByte_Ack1 || byte == UartControlByte_Nack; - if (r3 < STRESS_ACK_DROP_THRESHOLD && isAckLike && !uartState->receivingMessage) { - LogU("UartStress: Oops lost ack!\n"); + bool isAckLike = *byte == UartControlByte_Ack || *byte == UartControlByte_Ack0 + || *byte == UartControlByte_Ack1 || *byte == UartControlByte_Nack; + + if (dropRoll < STRESS_ACK_DROP_THRESHOLD && isAckLike && !uartState->receivingMessage) { + LogWrn("UartStress: Oops lost control!\n"); + return true; + } + + return false; +} + +static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { + if (UartStress_Active && stressByte(uartState, &byte)) { return; } -#endif switch (byte) { @@ -198,7 +208,7 @@ void appendByte(uart_parser_t *uartState, uint8_t byte) { if (uartState->txPosition < uartState->txLength) { uartState->txBuffer[uartState->txPosition++] = byte; } else { - LogU("Uart error: too long message in tx buffer\n"); + LogWrn("Uart error: too long message in tx buffer\n"); } } diff --git a/shared/uart_parser.h b/shared/uart_parser.h index 7a0ad2de2..89904dcee 100644 --- a/shared/uart_parser.h +++ b/shared/uart_parser.h @@ -62,6 +62,8 @@ // Variables: + extern bool UartStress_Active; + // Functions: void UartParser_InitParser( uart_parser_t* uartState, void (*receiveMessage)(void* state, uart_control_t messageKind, const uint8_t* rxBuffer, uint16_t len), void* userArg); From 1c5ec8ac50e9a19f2e39c46370a7a7d83e503700 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Tue, 6 Oct 2026 15:42:36 +0200 Subject: [PATCH 21/24] Bridge: Uhk60 compilation fixes. --- right/src/slot.h | 4 --- right/src/test_suite/test_suite.c | 48 ++++++++++++++++++++++++++++--- shared/uart_parser.c | 1 + 3 files changed, 45 insertions(+), 8 deletions(-) diff --git a/right/src/slot.h b/right/src/slot.h index 0711e7728..3bafa2f92 100644 --- a/right/src/slot.h +++ b/right/src/slot.h @@ -12,18 +12,14 @@ // Includes: -#ifdef __ZEPHYR__ #include "device.h" -#endif // Macros: #define SLOT_COUNT 4 #define IS_VALID_MODULE_SLOT(slotId) (SlotId_LeftKeyboardHalf <= (slotId) && (slotId) <= SlotId_RightModule) -#ifdef __ZEPHYR__ #define CURRENT_SLOT_ID (DEVICE_IS_UHK80_LEFT ? SlotId_LeftKeyboardHalf : SlotId_RightKeyboardHalf) -#endif // Typedefs: diff --git a/right/src/test_suite/test_suite.c b/right/src/test_suite/test_suite.c index 7d31576f4..05f200c0a 100644 --- a/right/src/test_suite/test_suite.c +++ b/right/src/test_suite/test_suite.c @@ -1,5 +1,4 @@ #include "test_suite.h" -#include "messenger.h" #include "device.h" #include "test_hooks.h" #include "test_actions.h" @@ -21,6 +20,10 @@ #include "module.h" #include +#ifdef __ZEPHYR__ +#include "messenger.h" +#endif + #if defined(__ZEPHYR__) && DEVICE_IS_UHK80_LEFT #include "link_protocol.h" #include "connections.h" @@ -81,7 +84,22 @@ static const test_t* getCurrentTest(void) { return &AllTestModules[currentModuleIndex]->tests[currentTestIndex]; } -static bool advanceToNextTest(void) { +// Link tests need the left-right bridge, which only the UHK80 has. +static bool isSkipped(const test_t *test) { + return !DEVICE_IS_UHK80 && test->linkTestId != 0; +} + +static uint16_t runnableTestCount(const test_module_t *module) { + uint16_t count = 0; + for (uint16_t i = 0; i < module->testCount; i++) { + if (!isSkipped(&module->tests[i])) { + count++; + } + } + return count; +} + +static bool stepToNextTest(void) { currentTestIndex++; if (currentTestIndex >= AllTestModules[currentModuleIndex]->testCount) { currentModuleIndex++; @@ -90,6 +108,19 @@ static bool advanceToNextTest(void) { return currentModuleIndex < lastModuleIndexExclusive; } +// Stays on the current test if this device can run it, otherwise moves on to the first one it can. +static bool seekRunnableTest(void) { + bool inRange = currentModuleIndex < lastModuleIndexExclusive; + while (inRange && isSkipped(getCurrentTest())) { + inRange = stepToNextTest(); + } + return inRange; +} + +static bool advanceToNextTest(void) { + return stepToNextTest() && seekRunnableTest(); +} + extern hid_keyboard_report_t *ActiveKeyboardReport; // Repeats are re-runs of the whole test, not a wrap of the action index, so that each pass @@ -120,9 +151,11 @@ static void startTest(const test_t *test, const test_module_t *module) { TestSuite_LogSeparatorOnce(); LogU("[TEST] Running: %s/%s\n", module->name, test->name); } +#ifdef __ZEPHYR__ if (DEVICE_IS_UHK80_RIGHT && test->linkTestId != 0) { Messenger_Send2(DeviceId_Uhk80_Left, MessageId_Command, MessengerCommand_StartTest, &test->linkTestId, sizeof(test->linkTestId)); } +#endif InputMachine_Start(test); OutputMachine_Start(test); @@ -446,7 +479,7 @@ uint8_t TestSuite_RunAll(void) { // Count total tests totalTestCount = 0; for (uint16_t i = 0; i < AllTestModulesCount; i++) { - totalTestCount += AllTestModules[i]->testCount; + totalTestCount += runnableTestCount(AllTestModules[i]); } LogU("[TEST] Running custom unit tests...\n"); @@ -464,6 +497,7 @@ uint8_t TestSuite_RunAll(void) { } // Start first test + seekRunnableTest(); const test_t *firstTest = getCurrentTest(); const test_module_t *module = AllTestModules[currentModuleIndex]; startTest(firstTest, module); @@ -489,6 +523,11 @@ uint8_t TestSuite_RunSingle(const char *moduleStart, const char *moduleEnd, cons const test_t *test = &module->tests[ti]; if (!streq(testStart, testEnd, test->name)) continue; + if (isSkipped(test)) { + LogU("[TEST] Test not supported on this device: %s/%s\n", module->name, test->name); + return 255; + } + // Found it - run with verbose logging, unless it is a repeated test: those run // hundreds of repetitions, so they log as in the full suite whichever way they are // started. @@ -536,7 +575,7 @@ static uint8_t TestSuite_RunModule(const char *moduleStart, const char *moduleEn lastModuleIndexExclusive = mi + 1; TestSuite_Verbose = false; - totalTestCount = module->testCount; + totalTestCount = runnableTestCount(module); LogU("[TEST] Running module: %s (%d tests)\n", module->name, totalTestCount); @@ -544,6 +583,7 @@ static uint8_t TestSuite_RunModule(const char *moduleStart, const char *moduleEn return 0; } + seekRunnableTest(); const test_t *firstTest = getCurrentTest(); startTest(firstTest, module); TestHooks_Active = true; diff --git a/shared/uart_parser.c b/shared/uart_parser.c index 4db67855b..255816213 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -16,6 +16,7 @@ #include "debug.h" // DEBUG_STRESS_UART #else #define LogU(...) +#define LogWrn(...) #define DEBUG_STRESS_UART false #endif From 37121cae9164be8336b3bfa864a92b1e1c997c7e Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 7 Oct 2026 15:47:31 +0200 Subject: [PATCH 22/24] Messenger: fix hypothetical races in the incoming message fifo. Take read node->next and then swapped fifo.first, so a put from the uart isr in between got linked behind an unlinked node: the message was lost and its pool slots leaked. Nested producers could also lose a message or run into the retry panic. Guard put and take by DISABLE_IRQ instead. This was never encountered in practice as far as we know. Co-Authored-By: Claude Opus 5.5 --- device/src/messenger_queue.c | 56 ++++++++++++------------------------ 1 file changed, 18 insertions(+), 38 deletions(-) diff --git a/device/src/messenger_queue.c b/device/src/messenger_queue.c index 262efbde9..afbbaeb9d 100644 --- a/device/src/messenger_queue.c +++ b/device/src/messenger_queue.c @@ -8,6 +8,7 @@ #include "logger.h" #include "thread_stats.h" #include "trace.h" +#include "atomicity.h" uint16_t MessengerQueue_DroppedMessageCount = 0; @@ -53,7 +54,6 @@ uint8_t* MessengerQueue_BlackholeBuffer = blackholeBuffer; POOL(regionPool, POOL_SIZE, POOL_REGION_SIZE); POOL(queuePool, POOL_SIZE, QUEUE_REGION_SIZE); -#define FIFO_RETRIES 10 struct k_fifo messageQueue; struct { @@ -62,49 +62,29 @@ struct { } fifo = { .first = NULL, .last = NULL } ; -static void panic(const char* reason) { - printk("%s", reason); - k_panic(); -} - +// Producers are the uart isr and the bt rx thread, the consumer is the main thread. static void fifoPut(messenger_queue_record_t* node) { - for (uint8_t tries = 0; tries < FIFO_RETRIES; tries++) { - if (fifo.first == NULL) { - node->fifo_reserved = NULL; - if (!__sync_bool_compare_and_swap((intptr_t*)&fifo.first, NULL, node)) { - continue; - } - fifo.last = fifo.first; - return; - } else { - node->fifo_reserved = NULL; - if (!__sync_bool_compare_and_swap((intptr_t*)&fifo.last->fifo_reserved, NULL, (intptr_t)node)) { - continue; - } - while ( fifo.last->fifo_reserved != NULL ) { - fifo.last = fifo.last->fifo_reserved; - } - return; - } + node->fifo_reserved = NULL; + + DISABLE_IRQ(); + if (fifo.first == NULL) { + fifo.first = node; + } else { + fifo.last->fifo_reserved = node; } - panic("failed to insert message into fifo\n"); + fifo.last = node; + ENABLE_IRQ(); } static messenger_queue_record_t* fifoTake() { - for (uint8_t tries = 0; tries < FIFO_RETRIES; tries++) { - if (fifo.first == NULL) { - return NULL; - } else { - messenger_queue_record_t* node = fifo.first; - messenger_queue_record_t* next = node->fifo_reserved; - if (!__sync_bool_compare_and_swap((intptr_t*)&fifo.first, (intptr_t)node, (intptr_t)next)) { - continue; - } - return node; - } + DISABLE_IRQ(); + messenger_queue_record_t* node = fifo.first; + if (node != NULL) { + fifo.first = node->fifo_reserved; } - panic("failed to retrieve next message from fifo\n"); - return NULL; + ENABLE_IRQ(); + + return node; } From 340dfbd046c13ac23f706b20a5839c5b1af1299c Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 7 Oct 2026 17:45:15 +0200 Subject: [PATCH 23/24] Bridge: clean packet dump code. --- device/src/keyboard/uart_bridge.c | 7 ++----- right/src/logger.c | 2 +- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index cf5ba7655..f90ec46f0 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -385,11 +385,8 @@ static void resend(uart_state_t *uartState, bool wakePeer) { } if (uartState->resendTries++ >= UART_RESEND_COUNT) { stats.giveUps++; - LogErr("Repeatedly failed to send a message! "); - for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { - LogErr("%i ", uartState->parser.txBuffer[i]); - } - LogErr("\n"); + LogErr("Repeatedly failed to send a message!\n"); + logFrameBytes(uartState->parser.txBuffer, uartState->parser.txPosition); uartState->resendTries = 0; uartState->txState = UartTxState_Idle; diff --git a/right/src/logger.c b/right/src/logger.c index c078a81af..937aead24 100644 --- a/right/src/logger.c +++ b/right/src/logger.c @@ -114,7 +114,7 @@ __attribute__((weak)) void c2usb_diag_dump(void) { void LogErr(const char *fmt, ...) { EXPAND_STRING(buffer); - LogConstantTo(DEVICE_ID, LogTarget_Uart, RED "WRN: " UNCOLOR); + LogConstantTo(DEVICE_ID, LogTarget_Uart, RED "ERR: " UNCOLOR); LogConstantTo(DEVICE_ID, LogTarget_Uart, buffer); } From 698ddc512b3a954fcf57e851755e4e11107f8fa6 Mon Sep 17 00:00:00 2001 From: Karel Tucek Date: Wed, 7 Oct 2026 17:46:04 +0200 Subject: [PATCH 24/24] Bridge: restart RX after a run of out-of-frame garbage. After a simultaneous cold start of both halves (battery-less, powered over the bridge cable) the UARTE receiver can end up corrupting the first byte after every idle gap, without raising any rx error: frames lose their Start byte, lone pings and acks are lost, and the link flaps. One rx restart cures it for good. The reset on every unexpected byte used to hide this, and was removed in 5d560fd2b (and compiled out with UART_LOWPOWER in 18.0.0-18.0.2). Bring the recovery back in a bounded form: three consecutive rx chunks with out-of-frame bytes and nothing valid in between restart RX, at most once per 100ms. Co-Authored-By: Claude Opus 5.5 --- device/src/keyboard/uart_bridge.c | 44 +++++++++++++++++++++++++++++-- 1 file changed, 42 insertions(+), 2 deletions(-) diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index f90ec46f0..678e35c8c 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -22,6 +22,9 @@ #define UART_FOREVER_TIMEOUT 10000 +#define UART_GARBAGE_CHUNKS_TO_RESTART 3 +#define UART_GARBAGE_RESTART_INTERVAL_MS 100 + #define UART_MAX_FRAME_WIRE_TIME_MS \ UART_FRAME_WIRE_TIME_MS(UART_MAX_BRIDGE_SERIALIZED_MESSAGE_LENGTH) @@ -58,6 +61,12 @@ typedef struct { uint8_t txWm; // watermark of the frame we await an ack for uint8_t rxWm; // watermark of the frame we owe an ack for + // Garbage watch, isr context only. See watchForGarbage. + bool chunkHadValid; + bool chunkHadGarbage; + uint8_t garbageChunks; + uint32_t lastRxRestartTime; + // Cycle stamps for the latency stats below. uint32_t sentCyc; // last uart_tx of a data frame uint32_t ackReqCyc; // last valid frame parsed (ack requested) @@ -108,6 +117,7 @@ typedef struct { uint16_t giveUps; uint16_t txSendFail; // uart_tx returned an error uint16_t unexpectedBytes; + uint16_t rxRestarts; // rx restarted because of a run of garbage latency_stats_t ackLoop; // sender: uart_tx of a frame -> its ack parsed latency_stats_t ackTurn; // receiver: frame parsed -> ack handed to uart_tx } uart_bridge_stats_t; @@ -165,10 +175,35 @@ static bool bridgeCanSleep(void *arg) { && (k_uptime_get() - uartState->lastLinkActivity) >= bridgeHoldoffMs(uartState); } +// The UARTE receiver can come out of a simultaneous cold start of both halves in a state +// where it corrupts the first byte after every idle gap: frames lose their Start byte, lone +// pings and acks are lost, and no rx error is ever raised. One rx restart cures it for good. +// A single frame tail after an ordinary rx teardown also arrives as garbage, so only a run +// of garbage chunks with nothing valid in between counts. +static void watchForGarbage(uart_state_t *uartState) { + if (uartState->chunkHadValid) { + uartState->garbageChunks = 0; + } else if (uartState->chunkHadGarbage) { + uartState->garbageChunks++; + } + + uint32_t currentTime = k_uptime_get(); + bool restartAllowed = currentTime - uartState->lastRxRestartTime >= UART_GARBAGE_RESTART_INTERVAL_MS; + if (uartState->garbageChunks >= UART_GARBAGE_CHUNKS_TO_RESTART && restartAllowed) { + uartState->garbageChunks = 0; + uartState->lastRxRestartTime = currentTime; + stats.rxRestarts++; + UartLink_Reset(&uartState->core); + } +} + static void bridgeReceiveBytes(void *state, const uint8_t* data, uint16_t len) { uart_state_t *uartState = (uart_state_t *)state; uartState->lastLinkActivity = k_uptime_get(); + uartState->chunkHadValid = false; + uartState->chunkHadGarbage = false; UartParser_ProcessIncomingBytes(&uartState->parser, data, len); + watchForGarbage(uartState); } // UART_RX_DISABLED hook (ISR context), fired on every RX teardown - ours and the @@ -224,6 +259,11 @@ static void logFrameBytes(const uint8_t* data, uint16_t len) { static void receiveMessage(void *state, uart_control_t messageKind, const uint8_t* data, uint16_t len) { uart_state_t *uartState = (uart_state_t *)state; uartState->lastLinkActivity = k_uptime_get(); + if (messageKind == UartControl_Unexpected) { + uartState->chunkHadGarbage = true; + } else if (messageKind != UartControl_InvalidMessage) { + uartState->chunkHadValid = true; + } switch (messageKind) { case UartControl_Ack: case UartControl_Ack0: @@ -672,9 +712,9 @@ void UartBridge_DumpStats(void) { LogU(" resends: timeout=%u nack=%u giveUps=%u txSendFail=%u txAborted=%u\n", (unsigned)stats.resendTimeout, (unsigned)stats.resendNack, (unsigned)stats.giveUps, (unsigned)stats.txSendFail, (unsigned)core->txAbortedCount); - LogU(" rx stopped: overrun=%u framing=%u break=%u other=%u disabled=%u\n", + LogU(" rx stopped: overrun=%u framing=%u break=%u other=%u disabled=%u garbageRestarts=%u\n", (unsigned)core->rxStoppedOverrun, (unsigned)core->rxStoppedFraming, (unsigned)core->rxStoppedBreak, - (unsigned)core->rxStoppedOther, (unsigned)core->rxDisabledCount); + (unsigned)core->rxStoppedOther, (unsigned)core->rxDisabledCount, (unsigned)stats.rxRestarts); dumpLatency("ackLoop (send->ack)", &stats.ackLoop); dumpLatency("ackTurn (rx->ack tx)", &stats.ackTurn); }