From 48e8517008e425ba15f4bd46a57837fb7b9b7701 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 29 Sep 2026 19:30:43 +0000 Subject: [PATCH 1/3] test(canopen): say where the block-upload deadline test aborted Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_The_Whole_Transfer failed once on CI at NotBe(CsAbort) without saying which of the 26 gaps it was or what the abort code was. The failure now reports the aborted object, the abort code, the sub-block index, the time between the abort and the last frame the peer sent, and the time into the transfer. FrameTap records each frame's arrival time so the idle time is not measured at dequeue. Refs #240 Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_016EcWb8FeLKbGWkDkZFYnvp --- .../CANopen/CanOpenSdoCorrectnessTests.cs | 40 ++++++++++++++++--- 1 file changed, 34 insertions(+), 6 deletions(-) diff --git a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs index 35d3d38..36abaa4 100644 --- a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs +++ b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs @@ -94,6 +94,11 @@ 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(); + var peerFrames = new List { transferStart }; // one entry per frame the peer has sent + 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); @@ -102,14 +107,32 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th await Task.Delay(gap); // first idle period: initiate response -> start Send(rawBus, CanOpenCobId.SdoRx(0x02), SdoBlockFrames.BuildEndResponse(SdoBlockFrames.CcsBlockUploadStart)); - + peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); + + // #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; 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"); + if (seg[0] == SdoFrames.CsAbort) + { + var (abortIndex, abortSubindex) = SdoFrames.ReadIndex(seg); + // 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(seg):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)"); + } (seg[0] & 0x7F).Should().Be(1, "blksize 1 restarts the seqno at 1 for every sub-block"); received.AddRange(seg.Skip(1)); subBlocks++; @@ -118,6 +141,7 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th await Task.Delay(gap); // idle period: segment -> our sub-block ACK Send(rawBus, CanOpenCobId.SdoRx(0x02), SdoBlockFrames.BuildSubBlockAck( SdoBlockFrames.CcsBlockUploadSubBlockAck, lastAckedSeq: 1, nextBlockSize: 1)); + peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); if (last) break; } subBlocks.Should().Be(segments); @@ -1357,7 +1381,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 +1394,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 +1404,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; } } From 8ab5d89a05dbf63168ed2e5b79cd793b22afdcf9 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 29 Sep 2026 19:50:02 +0000 Subject: [PATCH 2/3] test(canopen): report an abort that arrives after the final segment too The abort diagnostics of the block-upload deadline test covered only the segment reads. A server timeout in the gap after the 25th segment is queued behind the final ACK and was consumed as the end frame, so it failed the generic end-frame assertion without the abort code or timing. Both reads now go through one check. Refs #240 Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_016EcWb8FeLKbGWkDkZFYnvp --- .../CANopen/CanOpenSdoCorrectnessTests.cs | 33 +++++++++++-------- 1 file changed, 20 insertions(+), 13 deletions(-) diff --git a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs index 36abaa4..58618d0 100644 --- a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs +++ b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs @@ -117,22 +117,28 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th // 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); - if (seg[0] == SdoFrames.CsAbort) - { - var (abortIndex, abortSubindex) = SdoFrames.ReadIndex(seg); - // 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(seg):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)"); - } + 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++; @@ -147,6 +153,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), From 2ab4733e598477122c73679cfb5608a77b868d95 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 29 Sep 2026 19:57:06 +0000 Subject: [PATCH 3/3] test(canopen): timestamp peer frames before sending them The abort diagnostics of the block-upload deadline test recorded each peer frame after Send returned. If the test thread was descheduled in between, the server could time out and its abort arrive before that timestamp; the frame was then excluded and the idle time reported from the preceding one. Taking the timestamp before the send keeps it at or before the frame's arrival. With a 700 ms stall injected after an ACK and a 300 ms server timeout, the message read 402 ms before and reads 301 ms after. Refs #240 Co-Authored-By: Claude Sonnet 5.5 Claude-Session: https://claude.ai/code/session_016EcWb8FeLKbGWkDkZFYnvp --- .../TestCases/CANopen/CanOpenSdoCorrectnessTests.cs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs index 58618d0..4ed32ca 100644 --- a/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs +++ b/tests/CanKit.Pro.Tests/TestCases/CANopen/CanOpenSdoCorrectnessTests.cs @@ -96,7 +96,9 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th // For the failure message below: when the transfer began and when the peer spoke. var transferStart = System.Diagnostics.Stopwatch.GetTimestamp(); - var peerFrames = new List { transferStart }; // one entry per frame the peer has sent + // 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( @@ -105,9 +107,9 @@ public async Task Sdo_BlockUpload_Server_Deadline_Measures_Peer_Idle_Time_Not_Th (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)); - peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); // #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 @@ -145,9 +147,9 @@ void FailIfAborted(byte[] frame) 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)); - peerFrames.Add(System.Diagnostics.Stopwatch.GetTimestamp()); if (last) break; } subBlocks.Should().Be(segments);