test(server): capture logs through one process-wide subscriber - #96
Merged
Conversation
`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
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.
Closes #92.
The mechanism, established rather than guessed
The issue suspected
with_default's thread-locality — that some event wasemitted off-thread. That is not it:
resolve_key_custody()is synchronousand spawns nothing. The real cause is tracing's global, sticky callsite
interest cache.
As of tracing-core 0.1.36,
DefaultCallsite::register()computes acallsite's
Interestonce, viaDispatchers::rebuilder(), which whilehas_just_oneis true takes a fast path callingdispatcher::get_default— the registering thread's own subscriber, not the dispatcher registry.
A thread with none yields
NoSubscriber, whoseregister_callsitereturns
Interest::never(). That is cached, and theinfo!macro thenshort-circuits on
!interest.is_never()without ever consulting adispatcher. It stays
neveruntil some laterDispatch::newrebuilds.The interfering test is named:
config::tests::key_file_content_is_trimmedhits the same
server-heldcallsite with no subscriber installed. Under--test-threads=1the capture always registered the callsite with its owndispatch 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
b213b11:1 failure in 400runs under 48 competing processes, message identical to the issue's
(
startup log:with nothing after it). Two reviewers reproduced itindependently, in five further configurations.
under load on the final rebased tree here.
capture_logsbody it fails 200/200 at both-j1and-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 capturemakes
logs.contains(…) == false == expect_warnpass proving nothing.assert_capturedcloses 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 firewith 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
--nocaptureemits zero tracing-formattedlines, and
strings/nmon the built binary find no trace oftestlog.Adversarial review before opening
Three reviewers, distinct lenses, all MERGE-SAFE. Resolved since:
reviewers, then closed).
set_global_defaultraises the global max levelto TRACE while building the
Dispatch, but publishes the subscriber onlyafterwards, and never rebuilds — so a callsite first hit in that gap
passes
level_enabled!, resolves to no subscriber, and cachesneverwith nothing left to correct it. Demonstrated with a deterministic probe,
then closed with
rebuild_interest_cache()after installation.rationale asserted no callsite can ever register as
never, true onlyafter install; and
server.rsclaimed construction always logs thecustody line, when deleting that line leaves the capture non-empty.
tracing-core 0.1.36", so a Dependabot bump cannot silently falsify it.
with_default, and the same trap this PR set out to kill. Now adebug_assert!, which as a side effect also pins the drain property asurviving mutant had exposed.
Two things deliberately not claimed
DefaultCallsite::registerpushes toCALLSITESbefore computinginterest, so a callsite mid-registration when the rebuild sweeps can
still store
neveroveralways. That is the gap between a closurereturning and an atomic store, against a previous window spanning an
entire
set_global_default.rebuild_interest_cache()line is not covered by a test.install()runs once per process, so no in-process test can re-enterthe window; covering it would need its own integration binary and a
pubseam intotestlog. Its evidence is the probe above, not thesuite. Judged not worth widening the test surface for.
Verification
All five AGENTS.md commands re-run independently, after rebasing onto
current
mainso 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 stressiterations of
config::testsandtestlog::testsunder load, 0 failures.No production behaviour changes:
mod testlogis#[cfg(test)].