Repository navigation
pkgs/id: log_sync batch-collection tests are load-racy (5ms grace vs 2ms pacing), intermittently fail the nix check phase #3199
Description
Summary
The log_sync batch-collection tests race the production idle grace against wall-clock pacing from a second thread, and intermittently fail the pkgs/id check phase — which gates every NixOS system build (id-web → unit-id-primary.service → system toplevel). The assertions are correct; the timing margin is not.
Found while verifying the fix for #3160: with the five failures from that issue fixed, a nix build .#id-web check phase failed on exactly these two tests (1974 passed; 2 failed), and a local full-suite run failed one of them.
The failing tests
log_sync::tests::test_batch_collection_coalesces_paced_arrivals— batch length 2, expected 3 ("paced arrivals share one batch", src/log_sync.rs:1030)log_sync::tests::test_batch_collection_refused_stream_ends_at_the_total_cap— batch length 1, expected 256 ("a refused stream ends the batch at the total-arrival cap", src/log_sync.rs:1119)
A third sibling, test_batch_collection_grace_restarts_on_each_arrival, shares the design and the exposure.
Mechanism
collect_batch (src/log_sync.rs:554) waits out an idle BATCH_GRACE of 5 ms (src/log_sync.rs:86) for the next arrival, polling every 250 µs. The tests pace arrivals every 2 ms from a spawned thread. Any scheduler delay over 5 ms on either thread — routine on a loaded 16-core build machine (observed at load 12–24 with parallel builds running) — splits the batch or ends it early. Measured behaviour tracks load exactly:
- Solo re-runs at load ~12: 26/26 passes across the three pacing tests.
- Solo re-runs at load 20+:
refused_streamfailed 4 of 6. - Full-suite runs under load: at least one of the two fails most of the time.
Prior attempt
ce83056 ("fix(id): deterministic log_sync pacing & world_doctor mock", for #187) replaced the test-side first-arrival spin with blocking_recv. That removed one race but not this one: the pacer/grace wall-clock race is still live.
Impact
The id check phase sits on the critical path of every system build, so this is a load-dependent coin flip on every deploy, unrelated to whatever change is being shipped.
Suggested direction
Not prescribed, but one clean shape: give collect_batch an internal grace parameter (production call passes BATCH_GRACE; tests pass a generous grace), so the coalescing / grace-restart / cap behaviour is asserted without a 2 ms vs 5 ms wall-clock margin. The production 5 ms tuning stays exactly as is. These tests should not be excluded or ignored — what they assert is the ingest batching contract.
Acceptance criteria
- The three pacing-sensitive
log_syncbatch-collection tests pass deterministically under load (repeated full-suite runs at load 20+), not only in solo re-runs. - The fix removes the wall-clock race (deterministic synchronisation or an injected/controllable grace) rather than widening the 5 ms grace or the 2 ms pacing as a band-aid, unless the issue discussion records why a margin change is the right fix.
- The
pkgs/idcheck phase passes with these tests included — no check-phase exclusions.
Activity
dezren39 commentedon Oct 31, 2026
Intake review
Fleet monitor intake pass (protocol §5), 2026-10-31.
Related: Found while verifying the code#3160 fix; sibling build/test-health issues: code#3160 (5 failing lib tests), code#3195 (build-time review). Mechanism is fully documented in the issue body (collect_batch BATCH_GRACE 5 ms vs 2 ms test pacing, src/log_sync.rs).
Notes / risks / suggested approach: Still live: no merged PR resolves this as of this run (PR search for the issue and the test names returns only unrelated history). Notes: assertions are correct — the timing margin is the defect; a prior attempt (ce83056, for #187) already touched this area, so read it before changing the design. Risks: a naive grace bump re-flakes under higher load and slows production batching. Suggested approach: make the tests drive the grace deterministically (inject the clock/grace into collect_batch for tests), keep production timing unchanged.
fix(id): make the log_sync batch-collection tests deterministic (#3199)
Merge pull request #3375 from developing-today/fix/3199-log-sync-test…
dezren39 commentedon Nov 1, 2026
Fixed by #3375 (merge
0f4731ea0bf1dc3f9d071de521b2d4da2199a02c).Fix shape
collect_batchnow takes the idle grace as a parameter. The production caller (ingest_arrivals) passesBATCH_GRACE(5 ms) — production behaviour and tuning unchanged. The pacing-sensitive tests injectTEST_GRACE(250 ms) while keeping the production-like 2 ms pacing; the grace-restart test paces 200 arrivals (~400 ms) so its run still spans far longer than the injected grace and keeps proving the restart semantics. The refused-stream cap test now asserts the mid-stream property by checking the pacer has not finished when the batch returns at the cap, instead of a wall-clock elapsed comparison. No test deleted/skipped/ignored, no assertion weakened; the tally test that also paces was audited and is batch-boundary-invariant, so unchanged.Evidence (laptop)
test_batch_collection, 5 tests): passed in all 10log_sync-module runs and 5/5 dedicated consecutive runs, at 5-minute loads of ~58–105 — well past the loads (20+, and 70–156 tonight) that used to split batches at the 5 ms margin.log_syncmodule (19 tests): 3/3 consecutive clean runs after the disk incident below.pkgs/idcheck suite on the PR tree (nix build .#id-web, exit 0): 41 suites, 2389 passed, 0 failed, 36 ignored (lib suite: 1993 tests). Baseline tonight on the unfixed tree: 1986 passed / 1 failed (this test) — twice.Verification incident (environmental, resolved)
Mid-verification the laptop root disk hit 100% (3.2T used, 0 avail; 325k nix store paths), which made unrelated
log_syncsession tests fail progressively (store writes) and broke git operations.nix-collect-garbagefreed 1.2T (63% used now); the session tests returned to 19/19 on the same binary immediately after. Worth knowing: the disk filling is also a plausible contributor to tonight's extreme scheduler latency during the failed switch attempts.