Skip to content

test(server): capture logs through one process-wide subscriber - #96

Merged
plusky merged 1 commit into
mainfrom
fix/testlog-capture-race
Aug 12, 2026
Merged

test(server): capture logs through one process-wide subscriber#96
plusky merged 1 commit into
mainfrom
fix/testlog-capture-race

Conversation

@plusky

@plusky plusky commented Aug 12, 2026

Copy link
Copy Markdown
Owner

Closes #92.

The mechanism, established rather than guessed

The issue suspected with_default's thread-locality — that some event was
emitted off-thread. That is not it: resolve_key_custody() is synchronous
and spawns nothing. The real cause is tracing's global, sticky callsite
interest cache
.

As of tracing-core 0.1.36, DefaultCallsite::register() computes a
callsite's Interest once, via Dispatchers::rebuilder(), which while
has_just_one is true takes a fast path calling dispatcher::get_default
— the registering thread's own subscriber, not the dispatcher registry.
A thread with none yields NoSubscriber, whose register_callsite
returns Interest::never(). That is cached, and the info! macro then
short-circuits on !interest.is_never() without ever consulting a
dispatcher
. It stays never until some later Dispatch::new rebuilds.

The interfering test is named: config::tests::key_file_content_is_trimmed
hits the same server-held callsite with no subscriber installed. Under
--test-threads=1 the capture always registered the callsite with its own
dispatch alive, which is why serialising made it pass.

This matters for the fix: the issue's option 3 — serialise the
log-capturing tests behind a mutex — would not have worked, because the
interfering party is not a capturing test.

What changed

One permanent global default per test process, writing to a thread-local
capture slot. Every callsite then registers against a subscriber enabled
for everything. Captures stay thread-scoped, so tests stay parallel and no
mutex is needed.

Plus assert_captured / assert_logged, so an empty capture fails as
"captured nothing" rather than as a missing needle against an empty
haystack — which is exactly how #92 presented and why it was hard to
diagnose from a build log.

Evidence

  • Flake reproduced verbatim on a pristine b213b11: 1 failure in 400
    runs under 48 competing processes, message identical to the issue's
    (startup log: with nothing after it). Two reviewers reproduced it
    independently, in five further configurations.
  • Fixed tree: 0 failures in 3000+ runs across reviewers, plus 0/150
    under load on the final rebased tree here.
  • The reproducer test is deterministic: reverted to the old
    capture_logs body it fails 200/200 at both -j1 and -j32.

The I12 angle

!logs.contains("hush-key") is trivially satisfied by an empty capture.
At the config.rs site that was never silent — the positive assertion above
it failed loudly, which is how the flake surfaced. The genuinely silent
hole was in server.rs, the ("", false) arm, where an empty capture
makes logs.contains(…) == false == expect_warn pass proving nothing.
assert_captured closes that one.

Verified by mutation: deleting the positive assertions while the writer
discards leaves the I12 test green over a provably empty capture;
adding a real leak (key={} on the custody line) makes the negative fire
with the key in the message. The negative assertion itself is unchanged
character-for-character.

Blast radius did not grow: capture buffers are byte-identical under both
implementations modulo timestamps, no reqwest/hyper/wiremock event reaches
them, a 117-test run with --nocapture emits zero tracing-formatted
lines, and strings/nm on the built binary find no trace of testlog.

Adversarial review before opening

Three reviewers, distinct lenses, all MERGE-SAFE. Resolved since:

  • The fix had a residual window of its own (found independently by two
    reviewers, then closed). set_global_default raises the global max level
    to TRACE while building the Dispatch, but publishes the subscriber only
    afterwards, and never rebuilds — so a callsite first hit in that gap
    passes level_enabled!, resolves to no subscriber, and caches never
    with nothing left to correct it. Demonstrated with a deterministic probe,
    then closed with rebuild_interest_cache() after installation.
  • Two comments that claimed more than the code delivered (fixed). The
    rationale asserted no callsite can ever register as never, true only
    after install; and server.rs claimed construction always logs the
    custody line, when deleting that line leaves the capture non-empty.
  • Prose naming private tracing-core internals now carries "as of
    tracing-core 0.1.36", so a Dependabot bump cannot silently falsify it.
  • Nested captures silently discarded the outer one — a regression vs
    with_default, and the same trap this PR set out to kill. Now a
    debug_assert!, which as a side effect also pins the drain property a
    surviving mutant had exposed.

Two things deliberately not claimed

  1. A narrower residual window remains and is not closable from here.
    DefaultCallsite::register pushes to CALLSITES before computing
    interest, so a callsite mid-registration when the rebuild sweeps can
    still store never over always. That is the gap between a closure
    returning and an atomic store, against a previous window spanning an
    entire set_global_default.
  2. The rebuild_interest_cache() line is not covered by a test.
    install() runs once per process, so no in-process test can re-enter
    the window; covering it would need its own integration binary and a
    pub seam into testlog. Its evidence is the probe above, not the
    suite. Judged not worth widening the test surface for.

Verification

All five AGENTS.md commands re-run independently, after rebasing onto
current main
so the verified tree is the one that lands: cargo fmt --check, both clippy invocations, cargo test --workspace --all-targets --locked (436 passed, 0 failed), cargo deny check — plus 150 stress
iterations of config::tests and testlog::tests under load, 0 failures.

No production behaviour changes: mod testlog is #[cfg(test)].

`capture_logs` installed its fmt subscriber with `with_default`, which
sets only the calling thread's default. tracing caches a callsite's
Interest the first time that callsite is hit, computed from the
registering thread's default subscriber — as of tracing-core 0.1.36
Dispatchers::rebuilder takes its has_just_one fast path and asks
dispatcher::get_default. Under parallel tests a thread with no
subscriber can win that race and cache Interest::never(), after which
the info! macro short-circuits without consulting any dispatcher and
the capture comes back empty. That is issue #92:
key_file_content_is_trimmed hits the same server-held callsite with no
subscriber, and when it registered first the I12 startup-log test saw
an empty string — reproduced verbatim on this tree, 1 failure in 400
runs under load.

Install one permanent global default instead, once per test process,
writing to a thread-local capture slot. Every callsite then registers
against a subscriber enabled for everything; the capture stays
thread-scoped, so tests stay parallel and no mutex is needed. Rebuild
the interest cache right after installation: set_global_default raises
the global max level to TRACE while building the Dispatch but
publishes the subscriber only afterwards, and a callsite first hit in
that gap would cache never with nothing left to correct it.

Add assert_captured / assert_logged so an empty capture fails as
"captured nothing" rather than as a missing needle, and use them at
both capture sites. That matters most for the server.rs loop, whose
`false` arm asserts an absence an empty capture satisfies while
proving nothing. Nesting captures is now a debug assertion rather than
a silent loss of the outer one.

No production behaviour changes: mod testlog is #[cfg(test)].

Closes #92
@plusky
plusky merged commit 25a972a into main Aug 12, 2026
11 checks passed
@plusky
plusky deleted the fix/testlog-capture-race branch August 12, 2026 21:21
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.

Flaky: startup_log_states_mode_and_source_never_key_material_i12 fails with an empty captured log under parallel test execution

1 participant