Rare 20s timeout under coverage, unrelated to the mock-state leaks in #190

[Bccorb]

Follows #190, which fixed three state leaks and took the flake rate from roughly
15% to one failure in about 57 runs. This is the residual, which looks like a
different mechanism.

The observation

The husky pre-commit hook runs npm run coverage. On one commit it failed:

 ❯ tests/integration/internal/internal.spec.ts (25 tests | 1 failed) 20122ms
      × returns 500 when the anomaly query fails 20010ms

 FAIL  tests/integration/internal/internal.spec.ts
   > GET /internal/security/anomalies (additional branches)
   > returns 500 when the anomaly query fails
 Error: Test timed out in 20000ms.

Not reproduced in 16 subsequent coverage runs (8 parallel, 8 sequential), nor in
40 runs of vitest run (20 of each). So it is rare, and it only has been seen
under coverage.

Why it is probably not the #190 mechanism

The test is a single request against a handler that cannot hang on its own logic:

it('returns 500 when the anomaly query fails', async () => {
  (AuthEvent.findAll as any).mockRejectedValue(new Error('boom'));

  const res = await request(app).get('/internal/security/anomalies');

  expect(res.status).toBe(500);
});

getSecurityAnomalies in src/controllers/internalSecurity.ts is one
AuthEvent.findAll inside a try, with a catch that returns
500 {"error":"Failed to detect anomalies"}. The route is auth: 'access' plus
requireAdmin('read'); the spec mocks attachAuthMiddleware locally and
requireAdmin is mocked globally to call next(), so neither middleware can
swallow the request. There is no await in that path that can fail to settle.

A 20 second wait for that is not an ordering problem, which is what #190 was. It
looks more like the worker being starved: under --coverage the suite takes
~34s sequential against ~2s for vitest run, all 93 files share one worker under
--fileParallelism=false, and v8 coverage instrumentation is on top of that.

Worth checking

• Whether it only happens under --fileParallelism=false --coverage, which is
  what the pre-commit hook used at the time. The hook now runs the parallel
  coverage command, so reproducing may need the old flag explicitly.
• Whether an unhandled rejection is involved. mockRejectedValue sets the
  default implementation, so any straggler call to AuthEvent.findAll from an
  earlier test's fire-and-forget path would also reject, and an unhandled
  rejection can take the worker with it.
• Whether the 20s testTimeout is simply too tight for the slowest coverage runs
  on a loaded machine, in which case this is a threshold to raise rather than a
  bug. Worth measuring the p99 duration of the integration specs under coverage
  before assuming it is a hang.
• tests/integration/internal/internal.spec.ts is the second heaviest
  mockResolvedValueOnce user in the suite (14 of them), behind
  organizations.spec.ts (22). The one pre-Test suite is intermittently flaky, including in the sequential coverage run #190 timeout observed was in
  organizations.spec.ts. That may be a coincidence now that the queues are
  drained between tests, or it may mean something is still off in those two files
  specifically.

Why it matters

The hook runs the full coverage suite on every commit, so a rare flake still
blocks a commit that is fine, and the fix is to retry. That is the habit #190
was about breaking.

Acceptance

• The cause is identified, or the timeout is shown to be a threshold problem and
  adjusted with the measurement that justifies it
• 20 consecutive npm run coverage runs pass

[Bccorb]

Correcting the rate in the description, and it is not coverage-only

The "one failure in about 57 runs" above was measured on the branch for #215,
before #216 and #217 merged. On current main it is worse, and it reproduces
under plain npm run test:run, not just under coverage.

Measured today on main at e47f16f, full suite, no other load:

run 1 ok      run 5 ok       run 9  ok
run 2 ok      run 6 FAILED   run 10 ok
run 3 ok      run 7 ok       ...
run 4 ok      run 8 ok

Two failures across 23 runs of vitest run, roughly 9%, against the 1-in-57 this
issue was opened with. A third failure appeared in the pre-commit hook on an
unrelated branch. A following batch of 10 runs was clean, so the sample is noisy,
but it is clearly not a rare coverage-only event.

The failures seen

• organizations.spec.ts > updateOrganization > performs an empty update when no fields are supplied
• internal.spec.ts > GET /internal/security/anomalies (additional branches) > returns 500 when the anomaly query fails (the original 20s timeout)
• one further failure not captured

organizations.spec.ts passed 5 times out of 5 in isolation immediately after
failing in the suite, so this is still cross-test interference rather than a
broken test.

Both named files are the two heaviest mockResolvedValueOnce users in the suite,
22 and 14 respectively. That was noted as possibly coincidental when this issue
was filed. Two of three observed failures landing in those two files makes
coincidence less attractive as an explanation, and it is the first thing worth
checking.

What this changes about the diagnosis

The original text leaned on the timeout looking like worker starvation under
coverage instrumentation. That explanation does not cover a failure in
vitest run, which finishes in about 2 seconds. Something else is still leaking
between tests, and #190 closed only the three mechanisms it identified:

• mockReset draining the Once queue between tests
• draining fire-and-forget handler continuations in a global afterEach
• unstubEnvs / unstubGlobals

A fourth mechanism remains. The afterEach drain is a single setImmediate
turn, which covers a continuation chain that only awaits already-resolved
promises. A continuation that schedules real work, a timer or another macrotask,
is not covered, and would present exactly like this: rare, load-dependent, and
landing on whichever test runs next.

Suggested next step

Capture a failing run with full output rather than reasoning further. The loop
that produced the numbers above writes the whole run to a file on failure:

for i in $(seq 1 20); do
  npx vitest run > /tmp/run.txt 2>&1
  grep -qE '^ *Tests .*failed' /tmp/run.txt && cp /tmp/run.txt "/tmp/fail-$i.txt"
done

The assertion diff is what distinguishes a stray call on a shared mock from a
value arriving from the wrong place, and every attempt so far has either caught
only the FAIL line or been overwritten by the next run.

[Bccorb]

Spent a session on this. No fix yet, but the measurement this issue asked for is
now done and it rules out one of the three candidate explanations, and I caught a
second, distinct failure mode along the way. Writing it all down so the next
attempt does not start from scratch.

The timeout is not a threshold problem

The issue asked whether 20s is simply too tight, and suggested measuring the p99
before assuming a hang. Measured, over a full npm run coverage run
(--reporter=json, 1146 tests):

p50	p90	p99	p99.9	max
1.1ms	4.9ms	67ms	469ms	560ms

The slowest test in the entire suite under coverage is 560ms. The timeout is
36 times that. Nothing is anywhere near the limit, so a test that reaches
20000ms is not a slow test that needed a little more room, it is a test that
never completed. Raising testTimeout would only make the failure slower to
surface, and lowering it would be safe but would not fix anything.

The ten slowest, for reference:

560ms unit/routes/errorShapeCoverage.spec.ts
469ms unit/openapi/generatedContract.spec.ts
261ms integration/conformance/conformance.spec.ts
189ms unit/controllers/authentication.spec.ts
164ms unit/models/models.spec.ts
 99ms unit/services/sessionService.spec.ts
 81ms unit/config/bootstrapSystemConfigDefaults.spec.ts
 72ms unit/app.spec.ts
 70ms unit/services/messagingService.spec.ts
 70ms unit/config/getSystemConfig.spec.ts

Three hypotheses eliminated, by test rather than by reading

Leaked fake timers. The only vi.useFakeTimers() in the suite is
tests/unit/services/oauthService.spec.ts:479, and it is wrapped in
try/finally with vi.useRealTimers(). Not it.

Leaked NODE_ENV re-registering the rate limiters. src/app.ts registers
dynamicSlowDown and dynamicRateLimit only when NODE_ENV !== 'test', and
slowDown uses delayMs: (hits) => hits * 1000, which reaches 20s at 20 hits.
That looked like an exact match for a 20s stall, and
tests/unit/utils/signingKeyStore.spec.ts writes process.env.NODE_ENV 18
times with no afterEach to restore it, leaving it 'production'.

It is not the cause: process.env does not survive between test files. Proved
with a pair of throwaway specs run in order under --fileParallelism=false, one
setting NODE_ENV=production and a marker variable and restoring neither, the
other reading them. The second file saw NODE_ENV=test and the marker
undefined.

Worth noting because the comment in vitest.config.ts reads as though direct
process.env writes do leak between files. They do not. (The comment is about
vi.stubEnv/vi.stubGlobal specifically, which is a different mechanism and
which I did not test, so I have left it alone.)

The rate limiters at all. Moot regardless: tests/setup/mocks.ts:176 mocks
every limiter, dynamicRateLimit included, to a pass-through. No delay is
reachable from a test.

A second failure mode, which may be the same root cause

In 20 consecutive coverage runs I got one failure. It was not a timeout:

FAIL tests/integration/adminDashboard/adminDashboard.spec.ts
  > does not touch the /admin API namespace
AssertionError: expected 'text/html' to match /application\/json/

GET /admin/users, failing in 6ms, with no error logged by the app.

What makes this interesting: our app cannot produce that response.
/admin/users either matches the admin router (JSON), or falls through to the
catch-all in src/app.ts which answers 404 {"error":"Not Found"} (JSON). The
SPA fallback is scoped to /console and /console/*
(src/lib/adminDashboard.ts), so it cannot match /admin/users under Express 4.
text/html on that path is Express's own finalhandler, which only runs on an
app with no 404 handler of its own.

Four specs build bare Express apps, and
tests/unit/lib/defineRoute.authIntegration.spec.ts builds two with no 404
handler at all. A request reaching one of those would get exactly
text/html + Cannot GET /admin/users.

So the response appears to have come from a different server than the one under
test. supertest calls app.listen(0) per request and closes it in the end
callback (supertest/lib/test.js:63), which is roughly 1100 ephemeral bind and
close cycles per run across the worker pool.

That single mechanism would explain both symptoms: a request that reaches a
different live server returns the wrong body, and one that reaches nothing hangs
until the test times out. It also fits the 560ms-to-20000ms gap, since a hang is
not a slow test.

I could not prove it. I instrumented the assertion to dump status, headers, body
and the router stack on failure and ran 40 more coverage runs without
reproducing. Combined rate: 1 failure in 60 runs, consistent with the 1-in-57
in the description.

What I would try next

• Confirm or kill the wrong-server theory before changing anything: wrap
  net.Server.prototype.listen in a global setup, record (port, spec file, bind time, close time) for every supertest server in a run, and look for a
  port reused while another spec still expects to own it. That establishes the
  hazard without needing to catch a failure.
• If confirmed, the fix is to stop churning ports: bind one server per spec file
  in beforeAll and hand that to supertest, rather than a fresh
  app.listen(0) per request. That is roughly 400 call sites, so it wants the
  theory confirmed first.
• Do not raise testTimeout. The measurement above says the gap is not marginal.

Not done

The acceptance on this issue is not met. The cause is not identified, and I have
not run 20 consecutive clean coverage runs (I ran 60 with one failure).

[Bccorb]

Ran the port-tracing experiment. It killed my own theory and then found the
mechanism, so this is no longer guesswork.

Method

Patched net.Server.prototype.listen/close, http.Server.prototype.emit
(for request), and http.request in an extra setup file, writing a JSONL
trace of every server bind, close, incoming request, outgoing request, client
response and client error, tagged with pid and spec file. Then ran the suite in
a loop, saving the trace of any run that failed.

The wrong-server theory was wrong

From my earlier comment I suspected requests were reaching a server other than
the one under test. They are not. Over a full run of 439 servers:

• 0 port lifetime overlaps. No two servers ever held the same port.
• 0 client/server spec mismatches. Every request was served by the server
  its own spec bound.
• 0 port reuse. 439 binds produced 439 distinct ports, so the collision
  window essentially does not exist within a run.

Good news, since the fix I was contemplating was a ~350 call site refactor
premised on that theory.

The mechanism, from a traced failure

Caught this run, which is the symptom this issue describes:

FAIL tests/integration/webauthn/webauthn.spec.ts
  > POST /webauthn/register/finish > returns 500 when persisting the credential fails
Error: Test timed out in 20000ms.

Its trace:

sent: 439   served: 438     <- one request never reached any server
binds: 439  closes: 438     <- its server never closed
client responses: 438       client errors: 0
requests sent but never served: 1
  UNSERVED port 51341 /webauthn/register/finish from integration/webauthn/webauthn.spec.ts

So the client issued the request, no server ever emitted request for it, and
neither side ever errored. The connection went nowhere silently and the test
sat there until the 20 second timeout. The server never closed because supertest
closes it in the response callback, which never fired.

An earlier traced failure showed the same signature, with the server binding and
closing within 1ms having served nothing.

That is the hang. It is not slowness: measured separately, the slowest test in
the suite under coverage is 560ms against a 20000ms timeout.

Where it comes from

supertest/lib/test.js creates a new http.Server per request
(http.createServer(app) in the constructor), calls app.listen(0) in
serverAddress, reads the port synchronously, and closes the server in end().
That is roughly 439 create/listen/connect/close cycles per run, across the
worker pool. Occasionally one request is lost in that cycle.

Candidate fix, partly validated

supertest skips its own listen when handed an already listening server
(if (!addr) this._server = app.listen(0)), and then never closes it. So one
server per spec file removes the churn entirely:

beforeAll(async () => {
  app = await createApp();
  server = app.listen(0);
});
afterAll(() => server.close());
// request(server) instead of request(app)

Converted tests/integration/webauthn/webauthn.spec.ts this way as a trial:
64/64 pass. The 50 run confirmation was cut short (see below), so the fix is
validated as correct but not yet as effective.

Rolling it out by hand means ~350 call sites across 25 files. A better shape is
probably to mock supertest once in tests/setup/mocks.ts, wrapping the default
export so an Express app is swapped for a cached listening server per file, with
an afterAll to close it. One place, no spec churn.

A second, separate mechanism still unexplained

While hunting I collected 10 failures over 80 runs. Only one was a timeout. The
rest were wrong statuses in unrelated specs, for example:

authentication.spec.ts > rejects invalid identifier          expected 404 to be 400
systemConfig.spec.ts   > updates system config               expected 401 to be 200
organizations.spec.ts  > returns 404 when membership missing expected 401 to be 404
webauthn.spec.ts       > lets a request agree with the policy expected 404 to be 200

These are not the lost-request mechanism. The trace shows those responses
were genuinely produced by the correct app, so they are real answers, not
misrouted ones. POST /login returning 404 is notable because
src/controllers/authentication.ts has no 404 branch at all, so that can only be
the catch-all, meaning the route did not match on that one request while 33 other
tests in the same file matched it fine. That looks like residue of the #190 class
rather than this issue, and probably wants its own ticket once this one is fixed.

Caveat on rates: the tracer does synchronous file writes around listen, connect
and close, so it amplifies the race. 10 in 80 with tracing is not the untraced
rate, which measured 1 in 60 under coverage.

Status

Mechanism identified and evidenced. Fix identified and shown to be correct on one
file, not yet shown to reduce the failure rate. I stopped short of the rollout
because another branch (fix/validation-error-shape) is being worked in the same
tree and I did not want to interleave with it.

[Bccorb]

Built the fix the tracing pointed at: PR #224. It reduces the flake a lot but I
am not closing this, because the timeout is not demonstrably gone.

What shipped

tests/setup/supertestServer.ts wraps supertest's default export once in the
shared setup, swapping an app for a cached listening server and closing them in
afterAll. supertest only calls listen when address() is empty and only
closes a server it opened itself, so one server serves the whole spec file.
listen(0) binds synchronously, so there is no half-bound server handed over.
Binds per run drop from 439 to 39, and no spec file changes.

Measured, same machine, same commands

Configuration	Before	After
npm run test:run, 80 runs	failures observed	0
npm run coverage, 20 runs	1 in 60	0
npm run test:run with tracing, 80 runs	10	2

The 20 clean coverage runs are the acceptance this issue asked for, so that box
is ticked.

Why I am not closing it

Of the 2 remaining traced failures, one is still a 20 second timeout
(oauthProviders.spec.ts). Broken down by class:

Class	Before (traced, 80)	After (traced, 80)
Wrong status on a route that exists	9	1
20 second timeout	1	1

So the change clearly reduces overall flakiness, and it is aimed squarely at the
mechanism traced in my previous comment, but at this sample size 1 against 1 does
not show the timeout is fixed. It may be a second path to the same symptom.

Two honesty notes on the instrument:

• The tracer does synchronous writes around listen, connect and close, so it
  amplifies the race. It is a sensitive detector, not a realistic configuration.
• Post-fix the tracer became unreliable: it reports whole files as "unserved"
  while most of their tests demonstrably pass, so it under-records served in
  the shared-server regime. Its post-fix counts are indicative only, which is why
  the untraced rows above are the ones worth weighing.

Still wants its own ticket

The wrong-status class (a route that exists answering 404, or a mocked auth
middleware answering 401) is a separate mechanism. Pre-fix traces show those were
genuine answers from the correct app, not misrouted ones, and
src/controllers/authentication.ts has no 404 branch at all yet POST /login
produced one. This change appears to reduce that class as well, from 9 to 1, and
I cannot explain why it would, which is another reason to keep this issue open
rather than declare victory.