(test): wait on the real condition in the trace rotation tests - #150
Merged
Conversation
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).
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The flake
test/activity-trace.test.jsfailed 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:
node --teston 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.fs.mkdtempSyncinto a unique folder.The actual cause: the three rotation tests waited on a fixed
setTimeoutinstead of on the condition itself.pruneSegments()runs asynchronously from thestream.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, andclose()setsstream = nullsynchronously (activity-trace.js:194-198). When the still-pending prune callback then calledtrace('trace.prune-failed', …), theif (!stream && !write) return;guard atactivity-trace.js:178swallowed 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.jsis untouched — the production behaviour was never wrong, the tests were measuring it badly.The three fixed
setTimeoutwaits become awaitUntil(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 beforet.close(), removing the race with the pending callback.Evidence it is fixed
One green run proves nothing about an intermittent test, hence the repeats.
eslint: 0 errors.Reasoning written up in
docs/activity-trace.mdunder "Testing the async prune path"; the code carries a one-line pointer.