diff --git a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs index 35d3d38..4ed32ca 100644 --- a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs +++ b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs @@ -94,28 +94,60 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th server.ObjectDictionary.AddDomain(0x2B10, 0x00, payload, OdAccess.ReadOnly); using var tap = new FrameTap(rawBus, CanOpenCobId.SdoTx(0x02)); + // For the failure message below: when the transfer began and when the peer spoke. + var transferStart = System.Diagnostics.Stopwatch.GetTimestamp(); + // One entry per frame the peer sends, taken just *before* the send: a frame's arrival can then + // never precede its entry, even if this thread is descheduled after the send returns. + var peerFrames = new List { transferStart }; + static long Ms(long from, long to) => (to - from) * 1000 / System.Diagnostics.Stopwatch.Frequency; + Send(rawBus, CanOpenCobId.SdoRx(0x02), SdoBlockFrames.BuildBlockUploadInit( 0x2B10, 0x00, clientCrcSupported: false, blockSize: 1, pst: 0)); var initResp = tap.Next(ShortTimeout); (initResp[0] & 0xE0).Should().Be(SdoBlockFrames.ScsBlockUploadInitResponseBase); await Task.Delay(gap); // first idle period: initiate response -> start + peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); Send(rawBus, CanOpenCobId.SdoRx(0x02), SdoBlockFrames.BuildEndResponse(SdoBlockFrames.CcsBlockUploadStart)); + // #240: this assertion failed once on a CI runner without saying where. An abort is + // reported with the sub-block it interrupted, its code and how long the peer had really + // been idle when it arrived (the frame's own arrival time, not the moment it is dequeued), + // so the next occurrence tells a deadline that fires early in the transfer (a re-arm + // defect, which would recur at the same index) from one that fires at a random point (a + // stalled host). var received = new List(); var subBlocks = 0; + // Every gap can time out, including the one after the final segment, whose abort is then + // read as the end frame; both reads go through here. + void FailIfAborted(byte[] frame) + { + if (frame[0] != SdoFrames.CsAbort) + return; + var (abortIndex, abortSubindex) = SdoFrames.ReadIndex(frame); + // The abort may be dequeued after a later peer frame was sent; idle time is + // measured from the last one that preceded its arrival. + var lastPeerFrame = peerFrames.Last(t => t <= tap.LastArrival); + Assert.Fail( + "the server must not time out a transfer whose peer keeps answering, but it aborted " + + $"0x{abortIndex:X4}:{abortSubindex:X2} with code 0x{SdoFrames.ReadAbortCode(frame):X8} " + + $"after {subBlocks} of {segments} sub-blocks, {Ms(lastPeerFrame, tap.LastArrival)} ms " + + $"after the last frame the peer sent, {Ms(transferStart, tap.LastArrival)} ms into the " + + $"transfer (SdoServerTimeout {serverTimeout.TotalMilliseconds} ms, gap {gap.TotalMilliseconds} ms)"); + } + while (true) { var seg = tap.Next(ShortTimeout); - seg[0].Should().NotBe(SdoFrames.CsAbort, - "the server must not time out a transfer whose peer keeps answering"); + FailIfAborted(seg); (seg[0] & 0x7F).Should().Be(1, "blksize 1 restarts the seqno at 1 for every sub-block"); received.AddRange(seg.Skip(1)); subBlocks++; bool last = (seg[0] & 0x80) != 0; await Task.Delay(gap); // idle period: segment -> our sub-block ACK + peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); Send(rawBus, CanOpenCobId.SdoRx(0x02), SdoBlockFrames.BuildSubBlockAck( SdoBlockFrames.CcsBlockUploadSubBlockAck, lastAckedSeq: 1, nextBlockSize: 1)); if (last) break; @@ -123,6 +155,7 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th subBlocks.Should().Be(segments); var end = tap.Next(ShortTimeout); + FailIfAborted(end); (end[0] & 0xE3).Should().Be(SdoBlockFrames.ScsBlockUploadEndBase); SdoBlockFrames.ReadEndUnusedBytes(end[0]).Should().Be(0, "175 bytes fill 25 segments exactly"); Send(rawBus, CanOpenCobId.SdoRx(0x02), @@ -1357,7 +1390,7 @@ private sealed class FrameTap : IDisposable { private readonly ICanBus _bus; private readonly uint _cobId; - private readonly System.Collections.Concurrent.BlockingCollection _frames = new(); + private readonly System.Collections.Concurrent.BlockingCollection<(byte[] Data, long Arrival)> _frames = new(); public FrameTap(ICanBus bus, uint cobId) { @@ -1370,7 +1403,7 @@ private void OnFrame(object? sender, CanReceiveDataView e) { if ((uint)e.CanFrame.ID == _cobId) { - _frames.Add(e.CanFrame.Data.ToArray()); + _frames.Add((e.CanFrame.Data.ToArray(), System.Diagnostics.Stopwatch.GetTimestamp())); } } @@ -1380,9 +1413,13 @@ public byte[] Next(TimeSpan timeout) { throw new TimeoutException($"No frame on COB-ID 0x{_cobId:X3} within {timeout}."); } - return frame; + LastArrival = frame.Arrival; + return frame.Data; } + /// Stopwatch timestamp at which the frame last returned by was observed. + public long LastArrival { get; private set; } + public void Dispose() => _bus.FrameObserved -= OnFrame; } }