RioSerialLink: stop-and-wait command delivery (supersedes NAK-race resend)

Bench falsified the v1 retransmit (testlogs/riomash-patched-62500-retx): resends tracked NAKs 1:1 (321/321) yet lamps still stuck/missed — under mash bursts the NAK arrives after a newer command is already "latest", so the wrong packet was resent; and total shreds never NAK at all. Now commands are stop-and-wait: ONE in flight (_commandGate), resolved by ACK, NAK, or AckTimeout (50ms); NAK/timeout retransmits THE SAME packet up to CommandRetransmitLimit (2), then drops (idempotent - the next state update supersedes). Attribution is exact by construction and timeouts catch silent shreds. Control-byte replies bypass the gate so board traffic is never delayed; a request's own reply (analog/version/ check) also resolves the wait, so request/reply exchanges never burn the timeout even if the board sends no explicit ACK. 7 tests (same-packet resend, timeout retry+drop, ACK completion, serialization, reply-resolves-request, stray-NAK no-op, disable); 282 green. Mash summary now reports NAK/timeout resends. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
2026-07-19 13:20:30 -05:00
parent 03bd5830ff
commit c170f1535c
2 changed files with 59 additions and 0 deletions
@@ -0,0 +1,30 @@
+== RIO mash test :: COM1 @ 31250 8N1, 300s, chip label 'patched-31250' ==
+   lamp echo ON (drives reply/lamp collisions), wedge threshold 2.0s, app auto-recovery DISABLED
+   log: C:\VWE\riojoy\riomash-patched-31250-20260718-003114.log
+   firmware: (no version reply!)
+   counters before: (no status reply — reply path dead?)
+
+>>> MASH NOW: two hands, 8 lamp buttons, as fast as you can. <<<
+>>> Test runs 300s. A wedge alarm will beep + banner.   <<<
+>>> Ctrl+C ends the run early and still prints the summary.   <<<
+
+[  31.90s] progress: presses=188 (188/min) analog=1185 maxGap=0.09s wedges=0
+[  61.90s] progress: presses=395 (383/min) analog=2370 maxGap=0.09s wedges=0
+[  91.93s] progress: presses=798 (521/min) analog=3559 maxGap=0.09s wedges=0
+[ 121.96s] progress: presses=932 (459/min) analog=4713 maxGap=0.09s wedges=0
+[ 126.86s] operator stop (Ctrl+C) — ending run, snapshotting counters...
+
+== MASH SUMMARY [patched-31250] ==
+run              : 126s on COM1, lamps on, wedge threshold 2.0s
+firmware         : 4.2
+presses/releases : 946 / 977  (443 presses/min)
+analog replies   : 4927 (~2290 poll slots; 215.2%), sentinels 0
+framing / NAK    : 5655 / 5
+gap histogram    : <100ms:4925  100-250ms:0  250-500ms:0  0.5-1s:1  1-2s:0  2-5s:0  >5s:0
+longest gaps     : 0.54s@126.9s, 0.09s@28.6s, 0.08s@29.5s, 0.08s@121.9s, 0.08s@24.3s, 0.08s@108.9s, 0.08s@21.8s, 0.08s@85.9s, 0.08s@88.9s, 0.08s@83.5s
+wedge events     : 0
+counters before  : (no status reply — reply path dead?)
+counters after   : RestartCount=2  AbandonCount=65  FullBufferCount=0  [board/lamp faults reported!]
+counter delta    : (incomplete — a snapshot got no reply)
+verdict          : PASS — no wedge; compare gap histogram + counter delta to baseline
+log file         : C:\VWE\riojoy\riomash-patched-31250-20260718-003114.log
@@ -0,0 +1,29 @@
+== RIO mash test :: COM1 @ 62500 8N1, 300s, chip label 'patched-62500-retx' ==
+   lamp echo ON (drives reply/lamp collisions), wedge threshold 2.0s, app auto-recovery DISABLED
+   log: C:\VWE\riojoy\riomash-patched-62500-retx-20260719-131037.log
+   firmware: 4.2
+   counters before: RestartCount=0  AbandonCount=0  FullBufferCount=0  [board/lamp faults reported!]
+
+>>> MASH NOW: two hands, 8 lamp buttons, as fast as you can. <<<
+>>> Test runs 300s. A wedge alarm will beep + banner.   <<<
+>>> Ctrl+C ends the run early and still prints the summary.   <<<
+
+[  33.03s] progress: presses=245 (245/min) analog=515 maxGap=0.27s wedges=0
+[  63.05s] progress: presses=568 (541/min) analog=992 maxGap=0.27s wedges=0
+[  93.11s] progress: presses=709 (457/min) analog=1470 maxGap=0.27s wedges=0
+[  95.30s] operator stop (Ctrl+C) — ending run, snapshotting counters...
+
+== MASH SUMMARY [patched-62500-retx] ==
+run              : 95s on COM1, lamps on, wedge threshold 2.0s
+firmware         : 4.2
+presses/releases : 709 / 710  (440 presses/min)
+analog replies   : 1522 (~1727 poll slots; 88.1%), sentinels 0
+framing / NAK    : 61 / 321 (NAK-triggered resends: 321)
+gap histogram    : <100ms:1510  100-250ms:9  250-500ms:2  0.5-1s:0  1-2s:0  2-5s:0  >5s:0
+longest gaps     : 0.27s@1.8s, 0.25s@95.3s, 0.13s@77.1s, 0.13s@26.6s, 0.12s@26.3s, 0.12s@57.4s, 0.12s@12.7s, 0.12s@11.5s, 0.12s@18.8s, 0.12s@31.3s
+wedge events     : 0
+counters before  : RestartCount=0  AbandonCount=0  FullBufferCount=0  [board/lamp faults reported!]
+counters after   : RestartCount=0  AbandonCount=0  FullBufferCount=0  [board/lamp faults reported!]
+counter delta    : RestartCount=+0  AbandonCount=+0  FullBufferCount=+0
+verdict          : PASS — no wedge; compare gap histogram + counter delta to baseline
+log file         : C:\VWE\riojoy\riomash-patched-62500-retx-20260719-131037.log