test(j1939): stop asserting timing these two tests cannot measure - #101
Conversation
macos-latest has been red on main since e6afc0a, and red on and off across several branches before that. Neither cause is a product defect; both tests assert something the host, not the code, decides. StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriod asserted that the median inter-arrival is within [0.7, 1.6] x a 120 ms period. PeriodicSchedule skips a tick whose previous emission is still in flight and coalesces the ones that fell behind by advancing the anchor whole periods at a time -- so under load it emits at 2 x period by design, and the test failed the implementation for doing exactly what its remarks promise. Reproduced under an 8x CPU overload: 5 of 6 runs failed, medians 200..272 ms, clustering on 240 ms = 2 x 120. That is the scheduler being right. Grid alignment would be the correct property, and it is what the multi-frame sibling asserts -- but that test earns the resolution by deriving its period from a measured send time, so one period is several times the observation jitter. At 120 ms it is not measurable: these stamps come off a spectator bus, where one emission observed late beside one observed on time already moves a gap by ~50 ms, 40 % of the grid spacing. Two intermediate versions of this commit tried it anyway and failed 2/8 and 5/12 under the same load. So the test now asserts what survives a loaded host: every gap rounds to at least one slot (no bursting -- coalescing must advance the anchor, and half a period separates a real emission from 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). The collection loop already bounds the mean from above. Stamps move from DateTime.UtcNow to Stopwatch ticks: they are only ever subtracted, and a wall clock can step under them. Both assertions are load-bearing, checked by mutation: halving the schedule period and releasing skipped ticks back to back are each caught by the slot check; a 15 % fast rate, which rounds to one slot, is caught by the mean. ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaim polled for the Claiming state with `for (i < 20) await Task.Delay(10)` and then asserted the state was still Claiming, inside a 500 ms arbitration window. The budget is 200 ms nominal and bounded by nothing; when twenty hops overran the window the arbitration timer committed the address correctly and the test reported that as a defect. It now waits on the node's own AddressClaimChanged transition, so the cancel is issued at the start of the window rather than an unknown distance into it, and the claim task completing as cancelled is the witness that it landed inside. No assertion is weakened: the polled state gate was strictly weaker than the transition event that replaces it. Verified: 14/14 clean under the 8x overload that failed the old tests 5/6. Build 0 warnings / 0 errors with CI=true, suite 583/583, format clean, packages verified. Refs #92. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
PR SummaryLow Risk Overview
Reviewed by Cursor Bugbot for commit 10fae43. Bugbot is set up for automated code reviews on this repo. Configure here. |
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 555f28728d
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
Codex was right on both counts, and the first one is the serious one: the
reworked claim test no longer failed against the bug it exists for.
Cancelling on the Claiming transition is too early. BeginClaimRound publishes
Claiming before it registers the pending claim, and the arbitration deadline is
armed later still, by OnClaimAnnounceTxConfirmed once the announcement is
confirmed on the wire -- which returns early when the claim task is already
completed. So the cancel prevented the deadline from ever being armed,
OnClaimAnnounceElapsed never ran, and there was nothing left to commit the
address wrongly.
Measured, not argued. Restoring the full original regression -- dropping both
the teardown post and the already-completed guard in OnClaimAnnounceElapsed --
the version before the timing rework fails ("Expected node.ClaimState not to be
Claimed, but it is") while the reworked one passed 3 out of 3. The reworked test
had become decoration.
Two changes bring it back:
The cancel now waits for the address-claim announcement itself, seen on a
spectator bus. That is the event whose confirmation arms the window, and it
cannot be observed before the pending claim is registered, so the sequencing
matches what the test claims to exercise.
The post-cancel assertion is Be(NotClaimed) rather than NotBe(Claimed). A
missing teardown leaves the node wedged in Claiming, which NotBe(Claimed) waves
through -- that was the second half of why the test went quiet. NotClaimed is
the terminal state after a cancel inside the window, so this catches the
regression through the state machine even on a run where the sequencing lost its
race, instead of depending on the timer having fired.
Against the full restored regression the test now fails 5 out of 5, and it is
worth recording how: four runs caught it as Claiming and one as Claimed. The
one is the live-deadline path Codex asked for; the four are why the assertion,
not the sequencing, had to be the guarantee.
Separately, the per-gap floor added to the periodic test in the last commit is
removed -- it was unsound, and load found it. Each emission lands on its own
grid slot but late by however long the host stalled, so a late emission followed
by a punctual one legitimately closes the distance: a tick firing 200 ms behind
its slot leaves the next anchor only 40 ms away. Under an 8x CPU overload that
produced a 32 ms gap against a 120 ms period with the scheduler behaving
correctly. Third time an assertion on this test looked principled and was not,
which is the argument for keeping only what mutation testing shows is load
bearing.
The mean-gap bound is left as the sole assertion because it is both true of the
implementation -- distinct slots are one period apart, so lateness cannot
manufacture emissions -- and sufficient: all three mutations are still caught by
it alone (period halved: mean 60 ms; skipped ticks released back to back: mean
0 ms; rate 15 % fast: mean 102 ms, all against a 108 ms bound).
Verified: 18/18 clean under the 8x overload, 5/5 against the restored
regression, 5/5 on correct code. Build 0 warnings / 0 errors with CI=true, suite
583/583, format clean.
Refs #92.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
Codex P2 was right, and the test was worse than it said — fixed in
|
| test version | vs. restored regression |
|---|---|
before my rework (origin/main) |
fails — "Expected node.ClaimState not to be Claimed, but it is" |
| my reworked version | passes 3/3 |
So the test had become decoration, exactly by the mechanism described. One note for anyone reproducing it: dropping only the teardown post is not enough — the IsCompleted early-return in OnClaimAnnounceElapsed is a second, independent defence and keeps both versions green. Both have to go before the original behaviour is visible. That is also why my first mutation attempt showed nothing.
Two changes, because the suggested fix alone would not have been enough
1. Sequencing, as asked. The cancel now waits for the address-claim announcement itself, observed on a spectator bus. That is the event whose confirmation arms the window, and it cannot be seen before _pendingClaim is registered.
2. The assertion. NotBe(Claimed) → Be(NotClaimed). The review identifies this in passing — "the node remains Claiming with a null address, which satisfies NotBe(Claimed)" — and it turns out to be the load-bearing half. NotClaimed is the terminal state after a cancel inside the window, so a node wedged in Claiming is caught through the state machine rather than through the timer having fired.
Why both were needed: against the restored regression the reworked test now fails 5/5, but how it fails varies — four runs caught it as Claiming, one as Claimed. The single Claimed is the live-deadline teardown path the review wanted exercised, so the sequencing does reach it; the four Claiming runs are why sequencing could not be the guarantee on its own. Observing the announcement still does not strictly imply the deadline is armed — there is an actor hop in between — so the assertion carries the test and the sequencing makes the intended path the common one.
5/5 on correct code, 18/18 under an 8× CPU overload.
Found while validating this: my own periodic-test assertion was unsound
The per-gap "every gap rounds to ≥ one slot" floor I added in 555f287 is gone. Same family of error: each emission lands on its own grid slot but late by however long the host stalled, so a late emission followed by a punctual one legitimately closes the distance — a tick firing 200 ms behind its slot leaves the next anchor only 40 ms away. Under load that produced a 32 ms gap against a 120 ms period with the scheduler behaving correctly.
That is the third assertion on this test that looked principled and was not, which is the argument for keeping only what mutation testing shows is load-bearing. The mean-gap bound is now the sole assertion, and it is both true of the implementation (distinct slots are one period apart, so lateness cannot manufacture emissions) and sufficient — all three scheduler mutations are still caught by it alone:
| mutation | mean gap | bound |
|---|---|---|
| period halved | 60 ms | 108 ms |
| skipped ticks released back to back | 0 ms | 108 ms |
| rate 15 % fast | 102 ms | 108 ms |
Gate on 0f26fe7: build 0 warnings / 0 errors with CI=true, suite 583/583, format clean.
Generated by Claude Code
Brings in #100 (722a5a4). No conflicts: #100 is RawCan plus PendingKeyTests, this branch is J1939NodeTests only. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 6a6016ee0b
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
…inks the mean Codex, again correctly: the mean-gap bound can reject a run in which the scheduler did everything right. A first tick 239 ms behind its 120 ms slot makes Reschedule skip the missed anchor, so the second emission follows about 1 ms later; eight punctual gaps after that average to 106.8 ms against a 108 ms bound. Every emission in that run came from the documented fixed-rate coalescing path. A single collapsed gap moves a nine-sample mean by a ninth of a period, which is more than the whole allowance. Same lateness that killed the per-gap floor one commit ago, in a different disguise: emissions land on their own grid slots but late, and a window that starts late gives that time back inside the measurement. The median is immune to it. A minority of collapsed gaps cannot move it, dropped ticks push gaps to 2x or 3x the period and so move it away from the bound, and a schedule genuinely running fast moves every gap and takes the median with it. Checked against the scenarios rather than assumed: Codex's late-first-tick case gives a median of 120 ms, two collapsed gaps under heavy load still 120 ms, and a loaded run with dropped ticks 120 ms, while the three scheduler mutations give 60, 0.5 and 102 ms. Worth recording that the median was not a new idea here. The version of this test before the rework already read it; what was wrong with that version was the *upper* bound it paired with, 1.6x a period, which coalescing legitimately exceeds by design. Dropping the upper bound was the fix. Dropping the median along with it was an over-correction, and it cost two further rounds. Verified: all three mutations still caught (period halved, skipped ticks released back to back, rate 15 % fast); 16/16 clean under an 8x CPU overload. Build 0 warnings / 0 errors with CI=true, suite 614/614, format clean. Refs #92. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
…te it Codex is right that ci.yml carries a merge_group trigger and that a merge queue is exactly the mechanism for testing a queued branch against current main without a base merge. My rationale did not account for it. It is not right that the workflow "already handles this case". Checked rather than assumed: filtering CI runs by event merge_group returns zero. The trigger has never fired, because the queue is configured in the workflow but not enabled on the branch. Every merge to main, #100 and #101 today included, went in as a plain merge commit, and the base merges this wave paid for were real. So the rationale now says both things: the base-merge cost is real as things stand, and it has a known expiry the day the queue is enabled -- at which point that half of the argument goes away and the supervision half, which is the reason the rule exists, does not. A rule whose stated cost can quietly stop being true invites being dismissed later on exactly that ground. Filed as #106, because an inert guard reads as protection that is not there, and because the failure it was built for already happened once (#85, from two green pull requests merged four minutes apart). Markdown only; no code, project or workflow file touched, so no build, test or format result is claimed. Refs #85, #106. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
…after it The document was written mid-wave and then sat on a branch while #104, #107 and #108 happened. Publishing it unchanged would have put a stale derivation in the repository -- and stale in the worst place: its summary of the rules quoted the one-pull-request rule in the version the maintainer rejected, with an exception for problems the pull request itself caused. Corrected, and extended with what the second half produced, which is the more useful half: Seven Codex findings across #101, #104, #107 and #108, all seven upheld, four of them contradictions *between* paragraphs rather than defects in one. The last of those survived a re-read done specifically to hunt contradictions -- because I checked the paragraphs I had edited against each other, and the offending sentence was one I had not touched. It had been correct until a rule two commits earlier was inverted. That generalises to something worth having: inverting a rule silently invalidates every sentence referring to it, including outside the diff, so the question after a rule change is which statements it made false, not which lines it touched. Which is the same principle this file states for code, applied to prose -- and I had written that principle four commits before failing to apply it here. Also records the merge-race that happened twice (two corrections pushed shortly before a merge and lost with it) and the signal agreed in response, and adds #106 plus the still-unwritten "FERTIG -- mergebar" convention to the open items. Markdown in a directory mkdocs excludes from the site; no code, project or workflow file touched, so no build, test or format result is claimed. Refs #104, #106, #107, #108. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
Two findings from the review of this branch, both caused by extending the chronology from eight rows to eleven without re-reading what referred to it: - The header still said eight merged pull requests while the inventory two paragraphs below listed nine (#93, #96, #97, #98, #100, #101, #104, #107, #108). Corrected to nine. - A blank line between row 8 and row 9 terminated the Markdown table, so rows 9-11 rendered as plain pipe-delimited text. Removed. Two more of the same class that the review did not name: "in jedem der acht Faelle" in the cause section refers to the measurement failures only, so it is now "der ersten acht"; "von den acht Zeilen oben" means the whole table and is now "elf". The section on cross-paragraph contradictions records this occurrence, since the document reproduced the very error class it describes. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
What does this change?
macos-latestis red onmainright now (run 34743182101 one6afc0a), and has been red on and off across several branches before that. Neither cause is a product defect: both tests assert something the host decides, not the code. This makes them assert what is actually observable, without weakening a single real check.Refs #92, FR-J1939-007.
1.
StartPeriodicSend_SingleFrame_FiresAtConfiguredPeriodIt asserted the median inter-arrival lies within
[0.7, 1.6] ×a 120 ms period. ButPeriodicScheduledocuments that it skips a tick whose previous emission is still in flight and coalesces the ones that fell behind by advancing the anchor whole periods at a time — so under load it emits at 2 × period by design. The test was failing the implementation for doing exactly what its own remarks promise.Reproduced rather than assumed. Under an 8× CPU overload on 4 cores, the pre-existing test failed 5 of 6 runs, with medians of 200–272 ms clustering on 240 ms = 2 × 120. That is the scheduler being correct.
Grid alignment would be the right property — and it is already asserted, by the multi-frame sibling directly below. That test earns the resolution by deriving its period from a measured send time, so one period is several times the observation jitter. At 120 ms it is not measurable: these stamps come off a spectator bus, where one emission observed late beside one observed on time already moves a gap by ~50 ms, i.e. 40 % of the grid spacing. Two intermediate versions of this branch tried to assert it anyway and failed 2/8 and 5/12 under the same load before I accepted that the measurement, not the tolerance, was the problem.
So the test now asserts the two properties that survive a loaded host:
The collection loop already bounds the mean from above (N samples inside
ShortTimeout), so the rate is still pinned on both sides. Timestamps also move fromDateTime.UtcNowtoStopwatchticks — they are only ever subtracted from each other, and a wall clock can step under them.2.
ClaimAddressAsync_CancelDuringArbitration_TearsDownPendingClaimThe test means to sit inside a 500 ms arbitration window. Its waiting budget is nominally 200 ms but bounded by nothing — twenty
Task.Delay(10)hops on a stalled runner overrun the window, the arbitration timer commits the address correctly, and the test reports that as a defect.It now waits on the node's own
AddressClaimChangedtransition, so the cancel is issued at the start of the window instead of an unknown distance into it, and the claim task completing as cancelled is the causal witness that it landed inside. No assertion is weakened — the polled state gate was strictly weaker than the transition event replacing it.Verification
Both new assertions are load-bearing, checked by mutating the scheduler:
delay = Zero)Then 14/14 clean under the same 8× overload that failed the old tests 5 of 6.
Type of change
feat— new behaviour (minor release)fix/perf— bug or performance fix (patch release)docs/test/refactor/chore/ci— no release!in the title, plus aBREAKING CHANGE:footer explaining the migration)Tests only — no
src/change, so no release. The single commit istest:-typed.Checklist
dotnet build CanKit.Pro.sln -c Releasesucceeds — 0 warnings / 0 errors with-p:CI=truedotnet test CanKit.Pro.sln -c Releasepasses — 583/583 onnet10.0Also run:
dotnet format --verify-no-changesclean, anddotnet pack+eng/verify-packages.pyin a fresh directory (9 packages).One thing this does not do
It does not touch the multi-frame sibling, which also failed once on macOS (299 ms off a 180 ms tolerance). That one asserts grid alignment at a period it can resolve, so the fix there is not the same and is not obviously a tolerance either — it belongs with the rest of #92 rather than in a change whose point is that the other two were measuring the wrong thing.
🤖 Generated with Claude Code
https://claude.ai/code/session_011Zd6AyAtcZApgfRC2Rkitj
Generated by Claude Code