Skip to content

(test): wait on the real condition in the trace rotation tests - #150

Merged
devsuitup merged 1 commit into
mainfrom
fix/activity-trace-flake
Aug 23, 2026
Merged

(test): wait on the real condition in the trace rotation tests#150
devsuitup merged 1 commit into
mainfrom
fix/activity-trace-flake

Conversation

@devsuitup

Copy link
Copy Markdown
Owner

The flake

test/activity-trace.test.js failed intermittently in the full suite — one or two failures depending on the run — while passing 22/22 every time in isolation. Same family as the pre-commit hook that rejected a commit a few days ago and then went green on an immediate re-run.

A suite that lies intermittently invalidates every "CI is green" we exchange, so this was worth chasing to a proven root cause rather than a retry.

Root cause

Two hypotheses eliminated first, with evidence:

  • Cross-file pollution via a singleton: ruled out. node --test on this install (v24.18.0) spawns a separate child process per test file — verified empirically, two probe files report different PIDs. No shared memory is possible.
  • Shared scratch directory: ruled out by reading the code. Every test calls fs.mkdtempSync into a unique folder.

The actual cause: the three rotation tests waited on a fixed setTimeout instead of on the condition itself. pruneSegments() runs asynchronously from the stream.end() callback, and under the CPU and disk contention of the full suite that callback sometimes misses the fixed budget.

Worse than plain slowness, in "a failed prune is reported in the trace itself": t.close() ran after the fixed wait, and close() sets stream = null synchronously (activity-trace.js:194-198). When the still-pending prune callback then called trace('trace.prune-failed', …), the if (!stream && !write) return; guard at activity-trace.js:178 swallowed the line. Proven by temporary instrumentation of a copy of the module.

Searching for the same shape turned up a sibling: the base rotation test already polled, but with a 1000 ms budget that also proved too short under load (captured failing: 3 !== 2).

Fix

Test-only. activity-trace.js is untouched — the production behaviour was never wrong, the tests were measuring it badly.

The three fixed setTimeout waits become a waitUntil(check, {tries, intervalMs}) helper that polls the real condition (files on disk, array length, presence of the warning line) with a 10 s ceiling. In the failed-prune test the wait for the warning now happens before t.close(), removing the race with the pending callback.

Evidence it is fixed

  • Before: 1–2 intermittent failures in the full suite; always green in isolation.
  • After: 6 consecutive full runs — 671 tests, 664 pass, 7 skips, 0 fail every time — plus 5 consecutive isolated runs at 22/22.

One green run proves nothing about an intermittent test, hence the repeats.

eslint: 0 errors.

Reasoning written up in docs/activity-trace.md under "Testing the async prune path"; the code carries a one-line pointer.

Three async-prune tests in activity-trace.test.js waited a fixed
setTimeout instead of the actual on-disk/state condition, so they went
intermittently red under node --test's full-suite concurrency (68
files, real fs contention) while always passing in isolation.

Worse than plain slowness: the failed-prune test called close() before
its fixed wait elapsed reliably completed. close() nulls the trace's
stream synchronously, so a still-pending pruneSegments callback that
fires afterwards finds no stream and trace()'s own guard drops the
trace.prune-failed line with no error - a genuine ordering hazard, not
just an impatient timer.

All three tests now poll the real condition with a generous bound
instead of sleeping a duration, and the failed-prune test waits for the
warning to land on disk before calling close(). Reasoning and the
close()-vs-pruneSegments race are documented in
docs/activity-trace.md under "Testing the async prune path" rather
than left as inline comments.

Verified: 6 consecutive full `npm test` runs green (671 tests, 664
pass, 7 skip, 0 fail each) plus 5 isolated runs of the file alone.
Before the fix, the full suite failed intermittently on these same
tests (activity-trace.test.js:251/282).
@devsuitup
devsuitup merged commit 622a9aa into main Aug 23, 2026
7 checks passed
@devsuitup
devsuitup deleted the fix/activity-trace-flake branch August 23, 2026 21:01
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant