Three wall-clock-dependent tests fail intermittently across all three CI legs

[dborgards]

Observed over four CI runs of #91 — a branch containing no .cs changes at all, so none of these are caused by the code under test changing. Each failed exactly once and passed on a later run of the same or newer commit.

Test	Leg	Commit	Symptom
IsoTpStminTimingTests.Sender_Paces_Consecutive_Frames_According_To_Peer_Stmin	macOS	ff7012a	IsoTpTimeoutException: N_Cr timer expired waiting for next Consecutive Frame
J1939NodeTests.StartPeriodicSend_MultiFrame_KeepsFixedRate_Without_SendTime_Drift	macOS	ff7012a	gap off-grid by 196.9 ms against a 180 ms tolerance (30 % of the 600 ms period)
UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction	Windows	0a8812d	Expected a <UdsTimeoutException> to be thrown, but no exception was thrown

The cost is not the individual failure. It is that a green pull request can go red on the next run without anything changing, which makes "is CI red because of my change?" a question nobody can answer by looking.

Two of them are tolerance problems

J1939 measures the gap between periodic emissions with Stopwatch and asserts it sits within 30 % of a 600 ms period. 196.9 ms is over that. Worth noting before anyone reaches for a wider tolerance: the drift hypothesis the test guards against lands at half a period (~300 ms) off-grid, so widening to, say, 40 % would not blind it. But a tolerance picked to survive the slowest runner ever observed is a number that gets widened again the next time, and the test would stop meaning anything long before it stops failing.

ISO-TP measures CF-to-CF spacing against an advertised STmin of 5 ms with FastOptions(), and the receiver's N_Cr expired. Its own README already concedes the limit: "the effective CF spacing is STmin + OS scheduling latency … with no hard real-time guarantee under load". The test asserts a property the code cannot promise on a shared runner.

For both, the durable fix is to stop measuring wall-clock time: drive the actor's DeadlineScheduler from a virtual clock the test advances, so pacing and timeout behaviour are asserted deterministically. The real-time behaviour that genuinely depends on the host stays worth checking, but as a soft, non-gating observation rather than a build-breaking assertion.

The third one may not be a test problem at all

TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction sets P2ClientMax = 80 ms and has the ECU double Thread.Sleep(250) before replying. A 170 ms margin is not tight, so "the runner was slow" does not explain it on its own — the response cannot arrive early.

What can produce the observed result is the opposite of slowness at the point that matters: if the actor loop is starved for longer than 250 ms, then by the time it runs again both the expired deadline and the response are waiting, and the response wins the race. The client returns data instead of throwing.

If that reading is right, the test caught something real: a deadline that has already expired losing to a response that arrived afterwards. That is the same shape as #24, where an expired pending send stays in the FIFO and swallows the next echo, and it is what the L2 deadline primitive was introduced to prevent — an expiry that is guaranteed to be checked.

This is a hypothesis from one log, not a diagnosis. It should be reproduced under deliberate actor starvation before anyone decides which side the bug is on. Doing that first also decides the fix: if the client is right and the test is racy, it joins the two above; if the client is wrong, widening a tolerance would have hidden a defect.

Suggested order

1. Reproduce the UDS case under forced actor starvation, and settle whether the client or the test is at fault. This one first, because it is the only one that might be a product bug.
2. Move the ISO-TP and J1939 assertions onto a virtual clock.
3. Only then consider what, if anything, should still be measured against the wall clock, and make that non-gating.

Related: #52 covers the missing normative negative tests — a different gap in the same suite. This issue is about tests that exist and cannot be trusted.

[dborgards]

Six CI runs of #93: the list of three is not the shape of the problem

This issue names three tests. Watching one pull request through six runs turned up five distinct tests, never the same one twice, always exactly one failure out of 430+, always macOS or Windows:

Commit	Leg	Test	Symptom
6882a26	macOS	IsoTpCanFdTests.ClassicCan_RoundTrips_Payload_Length_Sweep(4095)	N_Cr timer expired
6882a26	Windows	UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction	no UdsTimeoutException thrown
4dd1d2c	macOS	J1939NodeTests.Send_InFlightAcrossReclaim_FailsWithNoAddressException	no J1939NoAddressException thrown
15aaf1c	—	—	all green
5d02992	macOS	J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere	5 s timeout
be1685b / c9ed350	—	—	all green
a720ffd	macOS	J1939NodeTests.StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod	median 208.9 ms vs 120 ms (allowed 84–192)

Only one of the three named here (the UDS one) actually reappeared. Two of the five are new, and one — StartPeriodicSend_SingleFrame_… — is the sibling of the J1939 test this issue lists, so the pair is a family rather than one bad test.

The decisive data point

a720ffd is this diff in full:

 CLAUDE.md | 55 -------------------------------------------------------
 1 file changed, 55 deletions(-)

A markdown deletion at the repository root. No project file, no source, no test, no build input. It cannot influence StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod through any mechanism, and it turned macOS red.

That closes the question this issue opens with — "is CI red because of my change?" — in the strongest possible way: on this suite, a commit that changes nothing at all has a real chance of failing.

Which changes the diagnosis

This issue reads as "three wall-clock tests need fixing". The evidence says something else: on a shared runner, roughly one arbitrary wall-clock-dependent test fails per run. Four failures in six runs is around a 65 % chance of a red pull request per push, independent of content.

So a fix that widens tolerances on the three named tests would not move the number much — the next run would pick a different test from the same pool. The pool is what needs addressing, which is what this issue's own suggestion (2) already points at: move the assertions onto a virtual clock the test advances, rather than measuring the wall clock on a machine that is not ours.

Worth adding to that suggestion: the population is larger than three, so the work is better framed as "find every test that asserts on measured elapsed time and decide, per test, whether it can be virtualised or should become non-gating" than as three individual repairs.

On the UDS one specifically

It passed on 15aaf1c, be1685b and c9ed350 after failing on 6882a26. That does not settle this issue's hypothesis that it may be a real defect — intermittent passing is exactly what an actor-starvation race looks like. The suggested order in this issue (reproduce under forced starvation first) still stands and is still the right first step.

A measurement of reproduction rates under CPU contention was started and stopped again: the load generators it used starved the machine that the pull request's own validation needed. Anyone picking this up should use trap-based cleanup rather than kill $(jobs -p), which does not reliably reach background jobs in a non-interactive shell — that was the failure, twice.

---

Generated by Claude Code

[dborgards]

Another one, and it widens the population again

J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere, macOS leg, commit 4f7f817 on #98 (job):

J1939TpAbortException: J1939-TP Bam RX session timed out (T1) waiting for next TP.DT from 0x10
  at J1939TpChannel.UnwrapInboxItem  (J1939TpChannel.cs:262)
  at J1939TpTests.CollectAsync        (J1939TpTests.cs:1054)
Failed! - Failed: 1, Passed: 567, Skipped: 0, Total: 568

Same run, same commit: ubuntu-latest and windows-latest both green. The build was clean on all three.

Why this one is worth recording rather than shrugging at. #98 changes SPN decoding — thirteen files, none of them under CanKit.Pro.J1939Tp, CanKit.Pro.Actor or CanKit.Pro.RawCan. So this is the same shape as the original evidence in this issue: a timing failure on a branch whose diff cannot reach the failing code. I also ran this exact test 40 times locally on that tree beforehand — 0 failures — and the full suite passes locally at 568/568.

The tally is now five distinct tests, none repeating. ISO-TP STmin pacing, J1939 periodic-send drift, UDS timeout poisoning, and now J1939-TP BAM T1 — plus the one noted earlier. That non-repetition is the important property: it is not one bad test to fix but a class of them, all of which assert wall-clock behaviour on a shared runner. Each individual failure looks dismissible, which is exactly why the aggregate keeps being dismissed.

It also adds a fourth subsystem to the "suggested order" above. Step 2 currently names ISO-TP and J1939; the J1939-TP receive timers (T1/T2/T3/T4) belong in the same migration onto a virtual clock, and they are the timers with the most wall-clock assertions of any subsystem here.

The practical cost, stated plainly: every PR now has a meaningful chance of a red leg that says nothing about the change under review, and each one costs a re-run plus a written justification for why it is not the author's fault. That is the tax this issue is about.

---

Generated by Claude Code

[dborgards]

Sixth, ~25 minutes after the fifth, on a different PR: J1939NodeTests.StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod, macOS, 9a19447 on #97 (job).

Expected value to be between 84.0 and 192.0 because median inter-arrival (208.7 ms)
should approximate the configured period (120 ms), but found 208.709.

This one is not a new subsystem — it is the single-frame sibling of the test already in the table above, in the same file, failing the same way (that one: 196.9 ms off a 180 ms tolerance). #97's diff is eight CANopen files and touches no J1939, actor or reliability code.

That makes the pattern sharper rather than just longer: the two J1939 periodic-send tests have now both failed on macOS on unrelated branches, so it is the measurement approach that is unreliable, not one unlucky tolerance. Widening either number would have moved the failure to the other test.

Running tally: six failures, six different tests, none repeating, all on branches whose diffs cannot reach the failing code.

---

Generated by Claude Code

[dborgards]

Seventh occurrence — and the first repeat, which changes what this issue can conclude

UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction, macOS, e2a8a09 on #100 (job):

Expected a <UdsTimeoutException> to be thrown, but no exception was thrown.

Identical symptom and identical test to the third row of the table above, which was seen on Windows at 0a8812d. #100's diff is RawCan, one ISO-TP comment, docs and tests — nothing under CanKit.Pro.Uds, CanKit.Pro.Actor or the deadline scheduler.

Why this one is different from the previous six. Every earlier failure was a new test, which is what made "a population, not an instance" the right description. This is the first time a test has failed twice — and it is specifically the test this issue singles out as possibly a product bug:

A 170 ms margin is not tight, so "the runner was slow" does not explain it on its own — the response cannot arrive early. […] If that reading is right, the test caught something real: a deadline that has already expired losing to a response that arrived afterwards.

That hypothesis rested on a single log. Two independent observations, on unrelated branches and different operating systems, make the alternative — that a 170 ms margin was overrun twice by chance — harder to hold. It does not prove the product bug; it does move the prior.

It also sharpens the suggested order rather than changing it. Step 1 already says to reproduce the UDS case under deliberate actor starvation before deciding which side is at fault, on the grounds that it is the only one that might not be a test problem. That is now the step with the most evidence behind it, and it is cheap: force the actor loop to stall past 250 ms and see whether the client returns data instead of throwing. If it does, the defect is real and the test has been reporting it correctly all along — twice.

The shape is worth naming. #24, merged in #100, was an expired pending send that stayed matchable and swallowed the next echo. This is an expired deadline that stays losable and yields to a later response. Same failure mode at a different layer: something that should be dead still wins against what came after it. If the UDS reproduction confirms it, that is not a coincidence but a missing invariant — an expiry must be guaranteed to be observed before anything that arrives after it — and it would be worth checking whether any other deadline consumer has the same hole.

Running tally: seven failures, six distinct tests, one now seen twice, all on branches whose diffs cannot reach the failing code.

---

Generated by Claude Code

[dborgards]

Third failure of the same test, second on one branch — this needs the step-1 investigation

UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction, macOS, f75b40f on #100 (job). 599 of 600 passed; same assertion as before:

Expected a <UdsTimeoutException> to be thrown, but no exception was thrown.

The occurrence pattern on #100 is the useful part, because it rules out a specific alternative:

Head	This test
e2a8a09	failed
a37a20a	passed
d213e00	passed
f75b40f	failed

Alternating on four consecutive heads of one branch. That is not a regression introduced by any single commit — if it were, it would fail from that commit onward. It is a race that fires or does not.

It also is not #100's. That diff touches CanKit.Pro.RawCan's TX-confirm FIFO and dispatch; the assertion is about a UDS client deadline losing to a late response, which lives in ProtocolActor's scheduler. No shared code path, and the two heads where it passed contain the same RawCan changes as the two where it failed.

Where that leaves the hypothesis. This issue's reading is that the actor loop is starved past 250 ms, so by the time it runs again both the expired deadline and the response are waiting, and the response wins. Three observations, three different commits, two operating systems, on branches whose diffs cannot reach the code. "The runner overran a 170 ms margin, repeatedly, on exactly one of ~600 tests" is a weaker explanation each time it has to be repeated.

A note on shape, which may matter more than the count. #100 has now hit the same failure mode twice in code review, at a different layer:

• RawCan: an expired pending send poisons the echo FIFO and cascades into further timeouts #24 itself — an expired pending send stayed matchable and swallowed the next echo.
• A check-then-act in TryMatchEcho — the entry was tested for completion, then completed after the lock was released, so a timeout landing in between consumed the echo on behalf of a send that had already lost.

Both are something already resolved still winning against what came after it, and this UDS case is described in exactly those terms above. Three instances of one shape in one subsystem stops looking like coincidence and starts looking like a missing invariant: an expiry must be observed before anything that arrives after it, and claiming must be a single atomic transition rather than a test followed by an act. If step 1 confirms the UDS case, it is worth auditing every other deadline consumer for the same pattern rather than fixing this one instance.

Running tally: eight failures, six distinct tests, this one three times.

---

Generated by Claude Code

[dborgards]

This is now blocking main, and a fourth test joins the list

Correcting my comment from an hour ago in one respect: I framed the newest evidence around the UDS test. Re-running the same commit showed that was the wrong focal point.

macos-latest is red on main. Run 34743182101 on e6afc0a (the #98 merge) fails J1939NodeTests.StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod, 582/583. This is no longer only "a green PR can go red on the next run" — the default branch is red, which means the next PR to be checked against it inherits an ambiguous signal by default.

Two attempts of one commit failed with disjoint test sets. On #100's head f75b40f:

attempt	failures
1	UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_Same_Service_Transaction
2	J1939NodeTests.ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaim, J1939NodeTests.StartPeriodicSend_MultiFrame_KeepsFixedRate_Without_SendTime_Drift

Same binary, same commit, no overlap. That is worth recording because it closes off the per-commit-regression reading for good, and because it means the failure count per run is a sample from a distribution rather than a property of a particular test.

Running total on macOS across main and fix/rawcan-tx-confirm: five recorded failures, four distinct tests.

The fourth test is the clearest specimen yet, and it is squarely a test defect

ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaim failed with "Expected the enum to be J1939ClaimState.Claiming, but found J1939ClaimState.Claimed" — in its setup, not its assertion:

var opts = new J1939NodeOptions(Name(1)) { ClaimAnnounceTimeout = TimeSpan.FromMilliseconds(500) };
…
for (int i = 0; i < 20 && node.ClaimState != J1939ClaimState.Claiming; i++)
    await Task.Delay(10);
node.ClaimState.Should().Be(J1939ClaimState.Claiming);

The test wants to sit inside a 500 ms arbitration window and cancel from within it. Its waiting budget is nominally 200 ms, but nothing bounds it: twenty Task.Delay(10) hops on a stalled runner overshoot 500 ms without difficulty, and by then the arbitration timer has correctly committed the address. The product did exactly what it promises. The test arrived after the window it meant to observe and reported the product's correct behaviour as a defect.

This one needs no virtual clock and no tolerance. It needs the poll loop replaced by a signal that is causally tied to entering Claiming — the same correction I applied to my own test on #100 after writing a Thread.Sleep(50) into it, which is the anti-pattern this issue is about.

It also sharpens what "wall-clock-dependent" means here. Two different failure modes are being lumped together:

1. Tests whose observable genuinely is timing — the two periodic-send tests, ISO-TP STmin. These need the virtual clock in step 2, because there is no way to assert grid alignment without a clock.
2. Tests that merely use sleeps as a substitute for a happens-before edge — this claim test, and very likely the UDS one. These need no clock at all, only a deterministic signal. They are cheaper to fix and they are the ones failing most often.

Splitting the list that way makes step 2 smaller than it looked.

Amendment to the suggested order

Step 1 stands unchanged and stays first — the UDS case is still the only candidate product bug, and the starvation reading in the issue body is still the hypothesis to test. I would add a step between 1 and 2:

1b. Fix the category-2 tests — those using a sleep or a bounded poll loop where a signal would do. ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaim is the worked example: no clock abstraction needed, no tolerance to argue about, and it removes a recurring red without weakening a single assertion.

I have not touched any of these from #100 — that PR is RawCan and these are J1939/UDS/ISO-TP, and the base branch carries the failure independently of it. Recorded there as a stand-down rather than fixed in place.

One thing worth stating explicitly, since it will be tempting when someone picks this up: the fix for the periodic-send tests is not a wider tolerance. The issue body already makes the argument (a tolerance chosen to survive the slowest runner observed so far gets widened again next time), and the newest data point supports it — 299 ms off-grid against a 180 ms tolerance, where the drift hypothesis the test exists to catch lands at ~300 ms. Widening far enough to be quiet would take the tolerance to where it can no longer distinguish the two implementations, i.e. the test would pass unconditionally. That is deleting the test with extra steps.

---

Generated by Claude Code

[dborgards]

Step 1b done: #101 takes the two tests that were red on main

#101 fixes StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod and ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaim. Two things I got wrong on the way there are worth recording, because both change the advice in this issue.

The single-frame test was not a tolerance problem. I filed it that way. It is a modelling problem: PeriodicSchedule documents that it drops in-flight ticks and coalesces late ones by advancing the anchor whole periods at a time, so 2 × period under load is correct behaviour, and the test's [0.7, 1.6] × period band called it a failure. Reproduced under an 8× CPU overload: 5 of 6 runs failed, medians 200–272 ms clustering on 240 ms = 2 × 120. The scheduler was right every time.

Grid alignment is not always the fix. My first two attempts replaced the median-gap band with the grid check the multi-frame sibling uses. They failed 2/8 and 5/12 under the same load. The reason matters for step 2: the sibling can resolve the grid because it derives its period from a measured send time, so one period is several times the observation jitter. At a 120 ms period it cannot be resolved at all — these stamps come off a spectator bus, where one emission observed late beside one observed on time moves a gap by ~50 ms, 40 % of the grid spacing. No tolerance setting separates a drifting scheduler from a busy host at that ratio.

So the general rule I would now put on step 2 is: before choosing an assertion, check that one period is large compared with the observation jitter on the channel you are sampling. If it is not, the property is not measurable there and asserting it produces a test that fails for reasons unrelated to the code — which is this whole issue. A virtual clock fixes this properly by removing the jitter; where a real clock has to be used, the period has to earn its resolution.

What survived: every gap rounds to at least one slot (no bursting — half a period sits between a real emission and slot zero, which jitter cannot cross), and the mean gap is at least one period (never faster than requested — one-sided in the direction load pushes). Both mutation-checked, so neither is decorative:

mutation	caught by
period halved	slot check (gap 1 = 56 ms → 0 slots)
skipped ticks released back to back	slot check (gap 1 = 1 ms → 0 slots)
rate 15 % fast — rounds to one slot	mean check (102 ms vs 108 ms)

Then 14/14 clean under the overload that failed the originals 5/6.

The claim test needed neither clock nor tolerance, as expected — it now waits on AddressClaimChanged instead of a twenty-hop poll, and the claim task completing as cancelled is the witness that the cancel landed inside the arbitration window. Confirms the category-2 split: those are cheap.

What is left here

• Step 1 — the UDS starvation investigation. Untouched and still the only candidate product bug; still the thing to do first.
• Step 2 — IsoTpStminTimingTests and StartPeriodicSend_MultiFrame_KeepsFixedRate_Without_SendTime_Drift. test(j1939): stop asserting timing these two tests cannot measure #101 deliberately leaves the multi-frame test alone: it asserts grid alignment at a period it can resolve, so its single macOS failure (299 ms off a 180 ms tolerance) is a different problem from the two just fixed, and folding it into a change whose whole point is that those two were measuring the wrong thing would have muddled both.

---

Generated by Claude Code

[dborgards]

Fifth distinct test, and one clean macOS pass — the "different one each time" pattern is now the strongest evidence here

J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere joins the list, on #100's head 83b7c59:

System.TimeoutException : Operation timed out after 00:00:05.
  at J1939TpTests.WithTimeout(Task task, TimeSpan timeout) J1939TpTests.cs:1443

613/614. This one is a hard wall-clock budget, not a tolerance and not a rate assertion: a BAM session plus two CM sessions running in parallel must all complete inside 5 seconds. On a loaded shared runner that is a statement about the host, and it is the third distinct shape in this issue now — alongside "assert a rate the scheduler does not promise" (the periodic tests) and "use a sleep where a happens-before edge is needed" (the claim test, fixed in #101).

The full macOS record across one branch:

head	failing test(s)
e2a8a09	UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_…
f75b40f attempt 1	UdsClientTests.TimedOut_Request_Does_Not_Poison_Next_…
f75b40f attempt 2	J1939NodeTests.ClaimAddressAsync_CancelDuringArbitration…, J1939NodeTests.StartPeriodicSend_MultiFrame_…
3a0cedd	(clean pass, 614/614)
83b7c59	J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere

plus main itself red on StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod. Five distinct tests across three packages, and a clean pass in the middle. That the identity of the failure changes run to run is worth more than the count: it says the suite has a population of tests each of which fails at some rate under load, not a handful of individually broken ones. Fixing them one at a time as they go red is a losing race, which is the argument for step 2 being a shared mechanism rather than a list.

Adding a fourth category

The issue body splits these into tolerance problems and a possible product bug; my earlier comment added the sleep-instead-of-signal category. This one is a fourth: a hard timeout on a whole scenario. It differs from the others in that there is nothing to re-express — the test is not asserting the wrong property, it is asserting a correct property with a deadline the host can miss. The only real fixes are a virtual clock (step 2) or making the budget a non-gating observation.

I did not fold this into #101. That PR's argument is that its two tests asserted properties they could not measure; this one measures fine and simply ran out of wall clock in a different package. Putting a third, differently-shaped problem in would weaken the case for all three.

Correction to my own step-2 advice

I wrote earlier that the general rule is to check that one period is large compared with the observation jitter. That is right for the rate tests and useless here — there is no period. The more general form, which covers all four categories:

Before asserting anything with a clock in it, name the quantity the host can perturb and check that the assertion's margin is large compared with it. If it is not, either remove the clock (a signal, a virtual clock) or stop gating on it. A margin chosen from observed runs rather than from that comparison is how all five of these were written.

Steps 1 (the UDS starvation investigation) and 2 remain open and unstarted.

---

Generated by Claude Code