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.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..a751ee4c5 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; } ATTR_PACKED connection_watermarks_t; typedef struct { 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/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 8fd9f44cd..678e35c8c 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -1,3 +1,4 @@ +#include #include #include #include @@ -20,8 +21,16 @@ #define THREAD_PRIORITY -5 #define UART_FOREVER_TIMEOUT 10000 -#define UART_RESEND_DELAY 64 -#define UART_RESEND_COUNT 5 + +#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) + +// 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, @@ -49,9 +58,24 @@ 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 + + // 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) 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; @@ -71,6 +95,55 @@ 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 ackStale; // ack for a frame other than the outstanding 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; + 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; + +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] @@ -102,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 @@ -129,22 +227,78 @@ static void setRxState(uart_state_t *uartState, uart_rx_state_t state) { wakeControlThread(uartState); } +#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'; + LogWrn(" %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) { + LogWrn(" %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; 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: - if (uartState->txState == UartTxState_WaitingForAck) { - uartState->resendTries = 0; - uartState->txState = UartTxState_Idle; - k_sem_give(&uartState->txBufferBusy); + 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) { + LogWrn("Uart: ack watermark mismatch\n"); + } + } 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 +307,9 @@ 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(); + uartState->rxWm = len > MessageOffset_Wm ? data[MessageOffset_Wm] : 0; setRxState(uartState, UartRxState_Ack); // message @@ -171,12 +328,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"); + LogWrn("Crc-invalid UART message received! %s %s\n", out1, out2 == NULL ? "" : out2); + logFrameBytes(uartState->rxBuffer, uartState->parser.rxPosition); setRxState(uartState, UartRxState_Nack); @@ -184,15 +337,14 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ } break; case UartControl_Unexpected: -#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. + // 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++; BridgeDbg("BRIDGE RX unexpected byte\n"); -#else - UartLink_Reset(&uartState->core); -#endif break; } } @@ -207,7 +359,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 @@ -223,14 +375,18 @@ 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); 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,27 +397,36 @@ 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); - int err = UartLink_Send(&uartState->core, &byte, 1); + if (isAck) { + // Measured once we hold the TX slot: includes waiting out our own in-flight frame. + recordLatency(&stats.ackTurn, uartState->ackReqCyc); + } + 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++; k_sem_give(&uartState->core.txControlBusy); } } // 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) { - if (uartState->resendTries++ > UART_RESEND_COUNT) { - LogU("Repeatedly failed to send a message! "); - for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { - LogU("%i ", uartState->parser.txBuffer[i]); - } - LogU("\n"); + if (wakePeer) { + stats.resendTimeout++; + } else { + stats.resendNack++; + } + if (uartState->resendTries++ >= UART_RESEND_COUNT) { + stats.giveUps++; + LogErr("Repeatedly failed to send a message!\n"); + logFrameBytes(uartState->parser.txBuffer, uartState->parser.txPosition); uartState->resendTries = 0; uartState->txState = UartTxState_Idle; @@ -273,9 +438,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 +500,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 +509,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, (uartState->rxWm & 1) ? UartControlByte_Ack1 : UartControlByte_Ack0, 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: @@ -354,24 +521,27 @@ 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); } 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; + if (ackOverdue) { + LogWrn("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); + resend(uartState, true); + } + + // Must be taken after the resend, which restamps lastMessageSentTime if (uartState->txState == UartTxState_WaitingForAck) { - uint32_t resendDelay = (UART_RESEND_DELAY << uartState->resendTries); - 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 + resendDelay); } } 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(); @@ -515,3 +685,36 @@ 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 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); + 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)stats.rxRestarts); + 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..3ef7e3357 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; } } @@ -111,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; @@ -252,7 +263,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) { diff --git a/device/src/keyboard/uart_link.h b/device/src/keyboard/uart_link.h index 7abff8b51..c87f1647f 100644 --- a/device/src/keyboard/uart_link.h +++ b/device/src/keyboard/uart_link.h @@ -41,6 +41,7 @@ // UART_WAKE_DISPATCH_DELAY_US, or that stop lands on the frame following a wake byte. #define UART_TRANSPORT_TIMEOUT_US 700 + // Typedefs: typedef enum { @@ -60,6 +61,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/messenger.c b/device/src/messenger.c index 8bad0d283..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" @@ -377,7 +378,16 @@ 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 + if (wm->rxIdxValid && rxIdx == wm->rxIdx) { + return false; + } + + wm->rxIdx = rxIdx; + wm->rxIdxValid = true; return true; } @@ -388,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/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; } diff --git a/device/src/shell/shell_commands.c b/device/src/shell/shell_commands.c index abde6803f..b22d5319f 100644 --- a/device/src/shell/shell_commands.c +++ b/device/src/shell/shell_commands.c @@ -39,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, @@ -523,6 +527,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 +609,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/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); } diff --git a/right/src/macros/debug_commands.c b/right/src/macros/debug_commands.c index 9646c28c9..1490aadd9 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() @@ -148,11 +149,58 @@ 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__) + UartBridge_DumpStats(); +#endif Trace_Print(LogTarget_Uart | LogTarget_ErrorBuffer, "Diagnostics reboot."); StateWormhole.persistStatusBuffer = true; Reboot(false); 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/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..05f200c0a 100644 --- a/right/src/test_suite/test_suite.c +++ b/right/src/test_suite/test_suite.c @@ -1,7 +1,9 @@ #include "test_suite.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 +15,21 @@ #include "mouse_controller.h" #include "layer_stack.h" #include "postponer.h" +#include "slot.h" +#include "key_states.h" +#include "module.h" +#include + +#ifdef __ZEPHYR__ +#include "messenger.h" +#endif + +#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 +59,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; @@ -69,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++; @@ -78,9 +108,38 @@ 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 +// 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 +151,12 @@ 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); OutputMachine_OnReportChange(ActiveKeyboardReport); @@ -104,127 +169,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(); - - // 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(); + bool changed = memcmp(bitmap, previous, length) != 0; - // 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 +469,7 @@ uint8_t TestSuite_RunAll(void) { passedCount = 0; partialCount = 0; failedCount = 0; + TestStatistics_Reset(); inInterTestDelay = false; isRerunning = false; singleTestMode = false; @@ -244,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"); @@ -262,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); @@ -287,16 +523,24 @@ 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 + 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. 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,13 +568,14 @@ 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; lastModuleIndexExclusive = mi + 1; TestSuite_Verbose = false; - totalTestCount = module->testCount; + totalTestCount = runnableTestCount(module); LogU("[TEST] Running module: %s (%d tests)\n", module->name, totalTestCount); @@ -338,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/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/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_defs.h b/shared/uart_defs.h index 305ed6d26..c653faf4c 100644 --- a/shared/uart_defs.h +++ b/shared/uart_defs.h @@ -34,6 +34,14 @@ #define UART_BRIDGE_PING_INTERVAL 200 #define UART_BRIDGE_TIMEOUT 700 + // One byte-time on the wire at 115200-8N1 (~87us), rounded up. A physical property of the + // link, so it outlives any particular power scheme. + #define UART_BYTE_TIME_US 90 + #define UART_FRAME_WIRE_TIME_MS(BYTES) (((BYTES) * UART_BYTE_TIME_US + 999) / 1000) + + #define UART_RESEND_DELAY 7 + #define UART_RESEND_COUNT 5 + #define UART_MODULE_PING_INTERVAL_MS 500 #define UART_MODULE_TIMEOUT_MS (UART_MODULE_PING_INTERVAL_MS*4) diff --git a/shared/uart_parser.c b/shared/uart_parser.c index c6c789fd5..255816213 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -9,12 +9,25 @@ #include "shared/module/uart_link.h" #endif +#include "device.h" + #ifdef DEVICE_ID #include "logger.h" +#include "debug.h" // DEBUG_STRESS_UART #else #define LogU(...) +#define LogWrn(...) +#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 + +#define STRESS_BYTE_FAULT_THRESHOLD (STRESS_RANDOM_RANGE / STRESS_BYTE_FAULT_RECIPROCAL) +#define STRESS_ACK_DROP_THRESHOLD (STRESS_RANDOM_RANGE / STRESS_ACK_DROP_RECIPROCAL) + #define CRC_SALT 0x1234 #define CRC_LEN UART_CRC_LEN @@ -25,17 +38,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) { @@ -50,16 +64,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(); +bool UartStress_Active = DEBUG_STRESS_UART; - if (r1 < 128) { - LogU("Oops!\n"); - byte = byte ^ r2; +// 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; + } + + 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 (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) { @@ -70,6 +108,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; @@ -157,7 +209,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"); } } @@ -174,6 +226,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..89904dcee 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 { @@ -55,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);