diff --git a/rio-firmware/testlogs/riomash-patched-62500-sw-20260719-132841.log b/rio-firmware/testlogs/riomash-patched-62500-sw-20260719-132841.log new file mode 100644 index 0000000..431b83c --- /dev/null +++ b/rio-firmware/testlogs/riomash-patched-62500-sw-20260719-132841.log @@ -0,0 +1,28 @@ +== RIO mash test :: COM1 @ 62500 8N1, 300s, chip label 'patched-62500-sw' == + lamp echo ON (drives reply/lamp collisions), wedge threshold 2.0s, app auto-recovery DISABLED + log: C:\VWE\riojoy\riomash-patched-62500-sw-20260719-132841.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. <<< + +[ 31.90s] progress: presses=115 (115/min) analog=492 maxGap=0.22s wedges=0 +[ 61.94s] progress: presses=224 (217/min) analog=968 maxGap=0.22s wedges=0 +[ 80.54s] operator stop (Ctrl+C) — ending run, snapshotting counters... + +== MASH SUMMARY [patched-62500-sw] == +run : 80s on COM1, lamps on, wedge threshold 2.0s +firmware : 4.2 +presses/releases : 285 / 285 (209 presses/min) +analog replies : 1279 (~1454 poll slots; 88.0%), sentinels 0 +framing / NAK : 22 / 48 (command resends NAK/timeout: 67) +gap histogram : <100ms:1261 100-250ms:17 250-500ms:0 0.5-1s:0 1-2s:0 2-5s:0 >5s:0 +longest gaps : 0.24s@80.5s, 0.22s@0.6s, 0.13s@47.9s, 0.13s@77.5s, 0.12s@21.2s, 0.12s@20.4s, 0.12s@22.9s, 0.11s@21.4s, 0.11s@49.3s, 0.11s@28.9s +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-sw-20260719-132841.log diff --git a/src/RioJoy.Core/Serial/RioSerialLink.cs b/src/RioJoy.Core/Serial/RioSerialLink.cs index 0ac9ed3..821e4fe 100644 --- a/src/RioJoy.Core/Serial/RioSerialLink.cs +++ b/src/RioJoy.Core/Serial/RioSerialLink.cs @@ -29,9 +29,20 @@ public sealed class RioSerialLink // ACK/NAKs those, and they must not queue behind a pending command. private readonly SemaphoreSlim _commandGate = new(1, 1); private readonly object _pendingGate = new(); - private TaskCompletionSource? _pendingAck; // true = ACK, false = NAK + private PendingCommand? _pending; private long _retransmits; + // The in-flight command: its command byte gates which inbound events may + // resolve it (a reply only resolves the MATCHING request — an analog reply + // still in USB transit from the previous poll must never "confirm" a lamp + // command that follows it; bench 2026-07-19). + private sealed class PendingCommand + { + public PendingCommand(byte command) => Command = command; + public byte Command { get; } + public TaskCompletionSource Tcs { get; } = new(); + } + public RioSerialLink(IRioTransport transport, RioSerialLinkOptions? options = null) { _transport = transport ?? throw new ArgumentNullException(nameof(transport)); @@ -115,29 +126,37 @@ public sealed class RioSerialLink { for (int attempt = 0; ; attempt++) { - var pending = new TaskCompletionSource(); - lock (_pendingGate) _pendingAck = pending; + var pending = new PendingCommand(packet[0]); + lock (_pendingGate) _pending = pending; await WriteAsync(packet, cancellationToken).ConfigureAwait(false); Task winner = await Compat.TaskCompat.WhenAny(new[] { - pending.Task, + pending.Tcs.Task, Compat.TaskCompat.Delay(_options.AckTimeout, cancellationToken), }).ConfigureAwait(false); - if (winner == pending.Task && pending.Task.Result) - return; // ACK'd + if (winner == pending.Tcs.Task && pending.Tcs.Task.Result) + return; // delivered (ACK, or the request's own reply) // NAK'd or timed out (a shred so complete the board never NAK'd). if (attempt >= _options.CommandRetransmitLimit) - return; // budget spent — drop; idempotent, next update supersedes + { + // Budget spent — drop (idempotent; the next update supersedes). + // Brief settle so a late straggler response can't land on the + // NEXT command's wait (strays with nothing pending are ignored). + lock (_pendingGate) _pending = null; + await Compat.TaskCompat.Delay(TimeSpan.FromMilliseconds(10), cancellationToken) + .ConfigureAwait(false); + return; + } Interlocked.Increment(ref _retransmits); } } finally { - lock (_pendingGate) _pendingAck = null; + lock (_pendingGate) _pending = null; _commandGate.Release(); } } @@ -206,11 +225,14 @@ public sealed class RioSerialLink case RioRxEventKind.ControlByte: if (ev.Byte is (byte)RioControl.Ack or (byte)RioControl.Nak) { - // Resolve the in-flight command (stop-and-wait): the board - // only emits ACK/NAK in response to our command packets. - TaskCompletionSource? pending; - lock (_pendingGate) pending = _pendingAck; - pending?.TrySetResult(ev.Byte == (byte)RioControl.Ack); + // Resolve the in-flight command (stop-and-wait). Safe to be + // type-blind here: the board's TX ISR sends pending ACK/NAK + // ahead of reply data, so a command's ACK cannot arrive + // after its successor starts (unlike replies, see + // DispatchTyped). + PendingCommand? pending; + lock (_pendingGate) pending = _pending; + pending?.Tcs.TrySetResult(ev.Byte == (byte)RioControl.Ack); } ControlReceived?.Invoke(ev.Byte); break; @@ -223,17 +245,23 @@ public sealed class RioSerialLink private void DispatchTyped(RioPacket packet) { - if (packet.Command is RioCommand.AnalogReply or RioCommand.VersionReply or RioCommand.CheckReply) + // A reply proves the MATCHING request landed, whether or not the board + // also sent an explicit ACK — but only the matching one: a reply still + // in transit from an earlier poll must never confirm an unrelated + // command (that type-blindness was the residual lamp-glitch hole). + RioCommand? resolves = packet.Command switch { - // A reply proves the corresponding request landed, whether or not - // the board also sent an explicit ACK — resolve the in-flight - // command so request/reply exchanges never burn the ACK timeout. - // (One command is in flight at a time, so the only stray case is - // an unsolicited reply resend — harmless: it can only release an - // idempotent command's wait early.) - TaskCompletionSource? pending; - lock (_pendingGate) pending = _pendingAck; - pending?.TrySetResult(true); + RioCommand.AnalogReply => RioCommand.AnalogRequest, + RioCommand.VersionReply => RioCommand.VersionRequest, + RioCommand.CheckReply => RioCommand.CheckRequest, + _ => null, + }; + if (resolves is not null) + { + PendingCommand? pending; + lock (_pendingGate) pending = _pending; + if (pending is not null && pending.Command == (byte)resolves.Value) + pending.Tcs.TrySetResult(true); } switch (packet.Command) diff --git a/tests/RioJoy.Core.Tests/Serial/RioSerialLinkTests.cs b/tests/RioJoy.Core.Tests/Serial/RioSerialLinkTests.cs index 8d93646..063643a 100644 --- a/tests/RioJoy.Core.Tests/Serial/RioSerialLinkTests.cs +++ b/tests/RioJoy.Core.Tests/Serial/RioSerialLinkTests.cs @@ -276,6 +276,33 @@ public class RioSerialLinkTests await run; } + [Fact] + public async Task AnalogReply_DoesNotResolve_PendingLampCommand() + { + var fake = new FakeTransport(); + var link = new RioSerialLink(fake, StopAndWait(limit: 1, timeoutMs: 250)); + + using var cts = new CancellationTokenSource(); + Task run = link.RunAsync(cts.Token); + + // Lamp command in flight; a straggler analog reply (from an earlier + // poll) arrives. It must NOT confirm the lamp — the lamp keeps waiting + // and is resolved only by its own ACK. + Task send = link.SendAsync(PacketBuilder.LampRequest(0x05, 0x02)); + await fake.NextWriteAsync(); + fake.Enqueue(PacketBuilder.Build(RioCommand.AnalogReply, new byte[10])); + + await Task.Delay(100); + Assert.False(send.IsCompleted, "stray analog reply must not resolve a lamp command"); + + fake.Enqueue((byte)RioControl.Ack); + await send.WaitAsync(Timeout); + Assert.Equal(0, link.Retransmits); + + cts.Cancel(); + await run; + } + [Fact] public async Task UnsolicitedNak_WithNothingPending_IsIgnored() {