test(canopen): say where the block-upload deadline test aborted

tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs

@@ -94,35 +94,68 @@ 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<long> { 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<byte>();
         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;
         }
         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<byte[]> _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;
         }
 
+        /// <summary>Stopwatch timestamp at which the frame last returned by <see cref="Next"/> was observed.</summary>
+        public long LastArrival { get; private set; }
+
         public void Dispose() => _bus.FrameObserved -= OnFrame;
     }
 }