Audit the test suite's 117 delay/sleep sites before converting any more of them

[dborgards]

Follow-up to #92 step 2 (#113). Not a conversion task — a counting task, and it should come before the next conversion.

Why this exists

#92 named three flaky tests in a table. #113 converted two of them and then found two more, each one by turning its own CI red:

found	test	how
#92	ISO-TP STmin pacing	listed
#92	J1939 fixed-rate BAM	listed
#113 round 3	DiscardPendingPdus_Drains_Completed_Pdus_And_Abort_Faults	macOS went red
#113 round 5	J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere	macOS went red

Each was measured against main before being attributed, so none was caused by the branch:

test	base	branch
DiscardPendingPdus_…	4 / 6	4 / 6
Parallel_Bam_And_TwoCm_…	6 / 6	4 / 6

Six runs each under 2× load on a four-core box.

The problem is the discovery method. Converting members as CI trips over them makes any pull request unbounded, and it works through the population in the order the runner happens to lose its bets rather than in any order that reflects risk. #113 spent three of its five CI rounds on tests it did not touch.

What to produce

There are 117 Task.Delay / Thread.Sleep call sites under tests/CanKit.Pro.Tests/TestCases, across twenty files:

J1939/J1939NodeTests.cs                     21     ProtocolActorTimerTests.cs        4
CANopen/CanOpenNodeIntegrationTests.cs      17     IsoTp/IsoTpFunctionalClientTests   4
IsoTp/IsoTpChannelIntegrationTests.cs       14     BusStateMonitorTests.cs           4
ProtocolActorTests.cs                       10     RawCanSubscriptionTests.cs        3
DeadlineTests.cs                             9     Uds/SimulatedUdsEcu.cs            2
J1939TpTests.cs                              8     IsoTp/IsoTpBusOffTests.cs         2
Uds/UdsClientTests.cs                        5     …and six files with one each
CANopen/CanOpenDynamicMappingTests.cs        5

Classify each into:

1. Waits for an effect — a bounded poll for something to become observable. Fine as it stands: a slow runner makes these slower, never wrong.
2. Assumes work completed in a window — await Task.Delay(50); /* it has surely arrived */. These are the defects. All four found so far are here.
3. Whole-test budgets — a WithTimeout(5s) around work whose duration a loaded runner controls. Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere is this shape, and it is not a sleep, so grepping for sleeps alone will miss it.

Output is a list, not a fix: which tests are in category 2 or 3, and for each, whether the interval it depends on runs on an actor that could be put on a VirtualClock.

What #113 already provides

VirtualClock with AdvanceAsync, AdvanceToAsync, RunUntilAsync and WaitUntilTimerArmedAsync; ProtocolActor.NextTimerDelayAsync as a sound arm-before-you-advance barrier; and injectable actors on IsoTpChannel and J1939NodeImpl.

J1939TpChannel and CanOpenNode still build their own actors, so anything in category 2 or 3 that lives in those layers needs the same seam first. Worth knowing before scoping, not after.

Two lessons from #113 worth carrying into any conversion

• A jump over a deadline cannot distinguish it from any shorter one. Both converted tests initially verified that pacing existed and not that it had the configured value; halving the interval left them passing. Bracket from both sides.
• The wire does not prove a timer is armed. A receiver sends flow control several statements before ArmNCr; a sender arms STmin from a thread-pool post. Move the clock in that window and the interval is armed from the new reading and never elapses.

Both were caught in review rather than by the tests failing, which is the argument for auditing rather than converting from memory.

[dborgards]

The audit, on f966cf5

Measured against main after #113 merged. Every count below is derived from a ledger with one row per grep hit, checked to match the grep's (file, line) set exactly — so the buckets add up to the total by construction rather than by my arithmetic.

First correction: 117 is 113

Four of the 117 matches are the words Task.Delay inside comments, three of them written by #92/#113 explaining a delay that is no longer there:

CanOpenNodeIntegrationTests.cs:201	"the fixed Task.Delay this used to sit on decided which behaviour was being asserted"
DeadlineTests.cs:86	"a 50 ms Task.Delay can overshoot by hundreds of milliseconds"
J1939NodeTests.cs:672	"twenty Task.Delay(10) hops inside a 500 ms window"
IsoTpChannelIntegrationTests.cs:418	"This used Task.Delay as a synchronisation primitive twice"

113 real call sites.

Second correction: the count is not a progress metric

Converting three tests moved it from 118 to 117.

	a967d00 (pre-#113)	f966cf5
sites under TestCases	118	117

Per file, only IsoTpChannelIntegrationTests.cs moved at all (15 → 14). IsoTpStminTimingTests.cs and J1939NodeTests.cs — the two files whose whole point was the conversion — are unchanged, because what those tests kept is a bounded poll, which is a delay and is not a defect. Anyone tracking this work by the grep count will read three sound conversions as one unit of progress.

The classification

bucket	sites
A — waits for an effect	33	bounded poll or bounded WhenAny won by the effect; a slow runner makes these slower, never wrong
B — assumes work completed in a window	55	the defects
C — a budget the runner controls	8	fixed-hop polls and windows
H — test-double or helper machinery	17	the delay models a peer, a driver or a WithTimeout helper, and asserts nothing about the SUT's timing
X — comment	4	above

63 sites in B and C. Split by which way they fail:

	sites
red	33	a correct implementation fails when the runner is slow — these are the CI flakes
green	20	a broken implementation passes — these are silent, and no CI run will ever find them
both	10	orderings established by sleeping; either failure is available

The green column is the part the flake-driven discovery method structurally cannot reach. Twenty assertions that cannot currently fail, and #113 has already shown twice what that is worth — the J1939 probe and the ownership tests were both in that class and both needed a reviewer, not a runner.

By layer:

layer	B+C sites	seam status
CANopen	20	CanOpenNode.cs:182 builds its own actor — needs the seam
ISO-TP	14	IsoTpChannel takes an injected actor (#113) — ready
J1939	9	J1939NodeImpl takes an injected actor (#113) — ready
J1939-TP	6	J1939TpChannel.cs:104 builds its own actor — needs the seam
UDS	4	UdsClientImpl reads Stopwatch.GetTimestamp() directly (:804) — needs a time seam, not an actor
RawCan L2	4	not an actor timer at all — these want a signal, not a clock
actor / deadline	4	the test constructs the actor — ready
BusStateMonitor	2	already takes an IProtocolActor (:129) — ready, no product change

Category 3 — the eight budgets

site	fails	note
J1939NodeTests.cs:838	red	fixed 20-hop poll = a 200 ms budget measured in hops
J1939NodeTests.cs:1086	both	fixed 20-hop poll before racing a reclaim into a live TP session
J1939NodeTests.cs:1204	red	N emissions at a period inside collectBudget
IsoTpChannelIntegrationTests.cs:831	red	fixed 50-hop poll = a 1 s budget in hops
IsoTpChannelIntegrationTests.cs:1207	red	as above
IsoTpChannelIntegrationTests.cs:1385	red	as above
IsoTpFunctionalClientTests.cs:441	red	waits out a product-side collection window measured on the wall clock
IsoTpFunctionalClientTests.cs:512	red	fixed 50-hop poll = a 500 ms budget in hops

for (int i = 0; i < 50 && !condition; i++) await Task.Delay(20); is the dominant shape. It reads as a bounded poll but it is a budget: each hop can overshoot, and when the hops run out the assertion executes anyway on a correct implementation. The issue already records that #92 caught this once — a poll that "gave itself twenty Task.Delay(10) hops inside a 500 ms window and overran it on a loaded runner". Seven more of them are still here. The mechanical fix is a deadline instead of a hop count, and it is not a virtual-clock conversion.

The known flake: not a shape problem, a missing argument

J1939TpTests.Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere is listed in this issue as a category-3 whole-test budget needing a fourth seam in J1939TpChannel. It is a budget, but the reason it is tight is one line.

The test sends a 200-byte BAM with J1939TpFactory.Open(busA, sourceAddress: 0x10) — no options, so Th is the default 50 ms. BAM DT frames are paced through J1939TpChannel.cs:661/:799 as _actor.Schedule(_options.Th, …), one hop per frame:

• TotalPackets(200) = (200 + 6) / 7 = 29 packets → 28 mandatory Th gaps
• 28 × 50 ms = 1400 ms of pacing that the test cannot avoid
• budget: ShortTimeout = 5 s

That leaves ~3.6 s of slack spread over 28 scheduling hops — about 107 ms of extra latency per hop before the budget is gone. On an idle box here the test reports 2 s.

Every other BAM test in the file shortens Th:

test	payload	th:	pacing	budget	margin
:71, :109, :137	100 B	5 ms	70 ms	5 s	71×
:312	1785 B	1 ms	254 ms	10 s	39×
:289	9 B	5 ms	5 ms	5 s	—
:523	20 B	5 ms	10 ms	5 s	—
:222 (the flaky one)	200 B	default 50 ms	1400 ms	5 s	3.6×

It is the only BAM test in the file that does not pass th:, and its margin is an order of magnitude tighter than any sibling. That is consistent with 6/6 failures on main under 2× load without needing any other explanation.

I have not changed it — this issue is a counting task and the fix belongs to whichever pull request takes this population. But it means the J1939-TP seam is not on the critical path for that test: th: TimeSpan.FromMilliseconds(5) takes the margin from 3.6× to roughly 70×, one line, no new machinery. Worth checking against the measurement before believing it, as ever.

Suggested sequencing

1. The eight category-3 budgets and the Th argument above. No product change, no seam, mechanical — hop counts become deadlines.
2. ISO-TP, J1939, actor/deadline and BusStateMonitor — 29 B+C sites whose seams already exist. BusStateMonitor is the cheapest: it has taken an injected actor since it was written.
3. CANopen — 20 sites, the largest single block, and 12 of them are the same NMT Start → await Task.Delay(50) → assert shape repeated across two files. Needs the test: put the ISO-TP and J1939 timing assertions on a virtual clock #113 seam in CanOpenNode first, and then one fix pattern covers most of them.
4. J1939-TP (6) and UDS (4) last; UDS needs a time seam rather than an actor one, which is a different change and overlaps RawCan: a blocking driver in Transmit stalls every subscription, because _pendingGate is held across it #102's area.

The RawCan L2 four are not clock problems at all and should not go on a virtual clock — they want an observable that says "the pump has drained", the same conclusion #113 reached for PeriodicEmissionsCompleted.

Two things this audit does not claim

The A/B/C assignment is judgement, not measurement: I read all 113 sites and classified each, and the direction column says which way I think each fails, but nothing here has been reproduced by making a runner slow. The two numbers that are measured are the site counts and the Th arithmetic above.

And the ledger is a snapshot. It is worth nothing the moment the tests move, which is the argument for working the list in the order above rather than re-deriving it later.

---

Generated by Claude Code

[dborgards]

Correction: six of the eight category-3 entries were wrong

I started on step 1 of my own recommendation — "the eight category-3 budgets, mechanical, hop counts become deadlines" — converted five of them, and then measured. The measurement says the change was unjustified and the reasoning behind it was backwards.

What I claimed

for (int i = 0; i < 50 && !condition; i++) await Task.Delay(20); … reads as a bounded poll but it is a budget: each hop can overshoot, and when the hops run out the assertion executes anyway on a correct implementation.

The second half does not follow from the first. A hop-count poll expands under load. If each Task.Delay(20) takes 100 ms on a loaded runner, fifty hops cover five seconds rather than one. The budget grows exactly when it is needed; it does not shrink. Converting it to a wall-clock deadline would have made these five more fragile under load, not less — a fixed 5 s deadline does expire where fifty stretched hops would not.

The measurement

The five affected tests (MultiFrame_Receive_Faults_When_Superseded_By_FirstFrame_Then_Overflow, Cancelled_Send_Holds_Gate_Until_InFlight_Bus_Tx_Completes, Rx_FirstFrame_Above_Classic_Max_Sends_Overflow_And_Does_Not_Allocate, Functional_Client_SendAsync_Puts_Frame_On_Bus, ReClaim_RejectsSendUntilNewClaimSucceeds), six runs each under 8× load on a four-core box:

	runs with a failure
main (f966cf5), hop polls as they stand	0 / 6
the branch, converted to wall-clock deadlines	0 / 6

Neither shape fails. There was no defect to fix, and I had written the false mechanism into five code comments before checking it. The conversions are reverted.

What #92 actually caught was a different shape: a hop poll nested inside an outer wall-clock window — "twenty Task.Delay(10) hops inside a 500 ms window". None of these five are nested in anything.

The corrected table

bucket	was	now
A — waits for an effect	33	38
B — assumes work completed in a window	55	56
C — a budget the runner controls	8	2
H — double or helper	17	17
X — comment	4	4

Five sites move C → A (J1939NodeTests.cs:838, IsoTpChannelIntegrationTests.cs:831, :1207, :1385, IsoTpFunctionalClientTests.cs:512). The unstated bound is a readability complaint, not a defect.

One moves C → B: J1939NodeTests.cs:1086. Looking at it properly, both of its loop's exit conditions (sendTask.IsCompleted, state no longer Claimed) are failure indicators, so on a healthy run it always burns all twenty hops and then races a reclaim in. That is a fixed settle wearing a poll's clothing — category 2, and it needs an observable for "the TP session has started", not a different bound.

Two genuine category-3 entries remain, both real wall-clock windows:

site	note
J1939NodeTests.cs:1204	22 samples at 120 ms inside a budget of 4× nominal; the comment itself says a loaded runner coalescing 3× needs "several times that", which leaves ~1.3×
IsoTpFunctionalClientTests.cs:441	waits out a product-side collection window; the margin was already widened once for macOS

Both have the J1939/ISO-TP seam available and are virtual-clock candidates rather than re-bounding candidates.

The red column drops from 33 to 28; green and both are unchanged at 20 and 10, and the green column remains the part no CI run will ever surface.

What did come out of step 1

The Th argument, which was the other half and is the real one. fix/test-budgets-measured-in-hops carries it alone: Parallel_Bam_And_TwoCm_Sessions_Do_Not_Interfere, six runs each under the same 8× load, 6/6 failures on f966cf5 → 0/8 with th: 5 ms. Mutation-checked, including a first attempt that did not discriminate.

The lesson, since this issue exists to stop exactly this

The audit's own recommendation was reasoned from the shape of the code and not measured, and five of its eight category-3 entries were wrong for the same reason the tests it audits are wrong: a claim about timing that was argued rather than run. The Th finding was arithmetic against a named quantity and survived; the hop-count finding was an intuition about load and did not. Worth carrying into whatever takes the remaining population — before re-bounding anything, reproduce it failing.

---

Generated by Claude Code

[dborgards]

A third budget family the audit missed, found by CI on #115

macos-latest went red on attempt 1 of #115 (b815df9, run 34855132254, job 104012737105):

CanKit.Pro.Tests.TestCases.Uds.UdsClientTests
  .ResponsePending_Loop_Aborts_When_Exceeding_MaxResponsePendingCount [FAIL]

Expected a <UdsProtocolException> to be thrown, but found <UdsTimeoutException>:
  UDS P2* timeout after 1000 ms waiting for response to service 0x22

Failed: 1, Passed: 631. The BAM test #115 fixes passed on that same run.

Not #115's

Measured, six runs each under 8× load on a four-core box:

revision	failures
main (f966cf5)	0 / 6
#115 (b815df9)	0 / 6

It does not reproduce on Linux at all, so the measurement establishes nothing about which revision is worse — it is the diff that settles it. #115 changes one options argument in three J1939TpFactory.Open calls inside J1939TpTests.cs; there is no path from there to UdsClientImpl. Attempt 2 came back green, which is not evidence either way and is recorded here only so nobody reads it as the resolution.

Why the audit did not have it

Not a near miss — a whole family I did not enumerate. The budget that decides this test is neither a sleep nor a test-harness ShortTimeout. It is a product timing option, set in the test's own options:

options: new UdsClientOptions
{
    P2ClientMax = TimeSpan.FromMilliseconds(500),
    P2StarClientMax = TimeSpan.FromSeconds(1),
    MaxResponsePendingCount = 2,
}

The ECU double answers with 0x78 responses 20 ms apart and the test asserts the client aborts on exceeding MaxResponsePendingCount. Each 0x78 restarts P2*, so the assertion needs the next one to arrive inside 1000 ms — nominally a 50× margin, but the path is an ISO-TP round trip across two channels plus the double's own loop, and the runner controls all of it. When P2* wins the race, the client raises the timeout it is entitled to raise and the test gets the wrong exception type. That is a red failure: a correct implementation, failed by the host.

My ledger has SimulatedUdsEcu.cs:145 — the delayBetween that paces those 0x78s — as bucket H, "models the ECU's own cadence, asserts nothing about the SUT's timing". That was right about the sleep and wrong about the test: the sleep is innocent, and the budget it races against was invisible to a grep for Task.Delay and ShortTimeout.

What that means for the population

The audit's 117/113 figure covers sleeps only. A per-test product timing option is a budget the runner can exhaust just as surely as a ShortTimeout, and the count of those is not yet known. UdsClientTests alone sets P2ClientMax / P2StarClientMax in several tests; J1939TpOptions (T1–T4, Tr, Th) and IsoTpChannelOptions have the same shape, and #115 is itself an instance — the fix there was to make a product timing option smaller.

So the enumeration wants a second pass over the options set in tests, not only the delays. I have deliberately not done that pass here: #115 is the pull request in hand and finishing it comes first.

This one belongs to the UDS row of the seam table, which already says what it needs: UdsClientImpl reads Stopwatch.GetTimestamp() directly at :804, so P2 and P2* cannot be driven by a test clock without a time seam. Same conclusion, arrived at by a different route than I expected.

---

Generated by Claude Code

[dborgards]

Second pass: the product timing options

Enumerating the budget family the sleep grep cannot see — timing options set per test. Three results, one of which is a flake on main and is now #116.

The population

family	where	values seen
IsoTpChannelOptions	5 helpers (FastOptions, FastIsoTp), ~85 call sites	NAs/NBs/NCr 500 ms everywhere except IsoTpBusOffTests (10 s, deliberate and documented: "if the send faults quickly, it must be the BusOff path"); 8 call sites override nBs/nCr to 120–2000 ms, and in those the deadline is the subject
UdsClientOptions	10 blocks in UdsClientTests, 1 in UdsExpiredDeadlineTests	P2ClientMax 80/100/120/150/500 ms and 5 s; P2StarClientMax 80/150/250 ms, 1 s, 5 s; TesterPresentPeriod 30/80 ms
J1939TpOptions	31 constructions	th: 0/1/2/5/60 ms (17 sites), t1: 120 ms / 5 s / 30 s, t3: 30 s, tr: 5 s
J1939NodeOptions	34 constructions	ClaimAnnounceTimeout 40/80/200/500 ms
CanOpenNodeOptions	7	sdoServerTimeout 150 ms

The useful split is not by type but by which way the option faces: is the assertion waiting for the deadline to fire (a slow runner only makes it surer — safe), or does the assertion need something to arrive before it (a slow runner fails a correct implementation — red)? P2StarClientMax in the macOS failure was the second kind. So was the Th in #115, and so is the one below.

The ISO-TP deadlines are not a risk — measured

I patched all 18 NAs/NBs/NCr defaults across the five helpers and walked them down, full suite each time:

value	idle
500 ms (as shipped)	632/632
100 ms	632/632
20 ms	632/632
5 ms	1 failure
1 ms	7 failures

The cliff is between 5 and 20 ms, so the shipped 500 ms carries a ≥ 25× margin, and the probe is demonstrably effective (it breaks 7 tests at 1 ms). That closes the family I had most suspected after the macOS failure.

The control caught me doing it again

My loaded probes each reported exactly one failure, at 200 ms, 50 ms and 20 ms. I was one step from writing that the deadlines are thin under load — the same "argued, not measured" move this issue keeps recording.

The control says otherwise. The unpatched suite under the same 8× load fails the same single test: J1939TpTests.Bam_MaximumPayload_Roundtrip. Every loaded reading was that flake, not the deadlines. The lesson is narrower than "measure": a probe whose failures you did not attribute has told you nothing — run the unmodified control under the same conditions before reading the probe.

The flake, and why it is not what it looks like

Bam_MaximumPayload_Roundtrip, 6/6 failures on main under 8× load, Operation timed out after 00:00:10. 1785 bytes is 255 TP.DT packets, so th: 1 ms puts 254 scheduled waits on the path.

th	idle	8× load
1 ms	548 ms	48–55 s
0	195 ms	1–3 s

I expected the cost to be CPU starvation of 255 actor iterations, which would have meant a virtual clock could not help and the J1939TpChannel seam was needed. The th: 0 probe says the opposite: a Schedule(1 ms) parks the loop and a parked loop wakes when the scheduler gets round to it; a zero-length wait is not a wait at all. ~200 ms per hop under load versus ~4 ms. So the fix is one option value, in #116 — not a budget (which would need 60 s) and not a seam.

The seam is still wanted for the six J1939-TP sites in the first pass. It is just not on this test's critical path.

What this adds to the classification

A fourth thing to look for, alongside the three categories: a scheduled wait multiplied by a packet count. It is invisible to both passes — the sleep grep does not see _actor.Schedule, and the options pass sees th: 1 ms and reads it as already-fast. What makes it dangerous is the multiplier, and the multiplier lives in the payload size.

Worth checking wherever a test picks a small non-zero interval "so it does not dominate the test": #115 and #116 are both that shape, found two hours apart, and neither was in the 113.

---

Generated by Claude Code

[dborgards]

The UDS flake, second occurrence — mechanism reproduced, fix measured

UdsClientTests.ResponsePending_Loop_Aborts_When_Exceeding_MaxResponsePendingCount failed macos-latest again, on #116 (d7d219f, job 104060338097), with the same message as on #115:

Expected a <UdsProtocolException> to be thrown, but found <UdsTimeoutException>:
  UDS P2* timeout after 1000 ms waiting for response to service 0x22

Two consecutive pull requests, neither of which can reach UdsClientImpl. It is a main flake blocking other people's work, which is a different thing from a main flake sitting in a list.

The mechanism, this time reproduced rather than inferred

Last time I described a plausible race and could not reproduce it on Linux. This time I made the margin the failing quantity instead of waiting for the host to do it: raise the ECU double's delayBetween from 20 ms to 1200 ms, against P2StarClientMax = 1 s.

Byte-for-byte the same failure, including the message. So the race is settled:

• the double answers with 0x78 pendings spaced by delayBetween: 20 ms (SimulatedUdsEcu.cs:145)
• each 0x78 restarts P2*, which the test sets to 1 s
• the assertion needs the third pending to arrive before P2* expires, so that MaxResponsePendingCount = 2 is what aborts the loop
• when the host stretches a 20 ms Task.Delay past a second, the client raises the timeout it is entitled to raise, and the test gets the wrong exception type

A 50× inflation of a 20 ms wait — the same order as the ~200× I measured for Schedule(1 ms) on a starved loop in #116. This is the third instance of one shape in two hours:

	the small wait	the budget it races	fix
#115	Th default 50 ms × 28 gaps	ShortTimeout 5 s	th: 5 ms
#116	Th 1 ms × 254 gaps	WithTimeout 10 s	th: 0
this	delayBetween 20 ms	P2StarClientMax 1 s	delayBetween: Zero

The fix, measured

delayBetween: TimeSpan.Zero. The test's subject is the count that bounds the pending loop, not the spacing between pendings, so removing the spacing removes the race without touching what is asserted.

• 3/3 green with the fix.
• Still catches what it exists for: making the bound unreachable — pendingCount > _options.MaxResponsePendingCount + 100 at UdsClientImpl.cs:860 — fails it 3/3.

Not a larger P2StarClientMax: that is the tolerance the working agreement exists to refuse, and it would be widened again the next time a runner is slower.

Status

Not fixed here. #116 is the pull request in hand, its red leg is attributable, and the maintainer has chosen to merge it on that attribution and take this as the next pull request. The fix above is ready and will go in on its own branch.

---

Generated by Claude Code