Convert nuncio-filter hand-rolled test subscriber to tracing-test (flaky callsite-Interest race) #375

New Issue

2026-08-01T00:19:42Z

KofTwentyTwo commented

2026-08-01 00:19:42 +00:00

(Migrated from github.com)

OBS-5 (#374) hit process-wide flakiness: a hand-rolled per-test tracing::Subscriber races tracing-core's callsite Interest cache under parallel runs. OBS-5 fixed nuncio-mail via the tracing-test crate. nuncio-filter/src/webhook.rs still uses the hand-rolled pattern and is exposed to the identical race. Convert to tracing-test. Low priority, real.

KofTwentyTwo commented

2026-08-12 16:04:18 +00:00

(Migrated from github.com)

Mechanism diagnosed while implementing #394 (PR #405), where the same failure was reproduced deterministically rather than as a flake — recording it here since it is the same defect class this issue tracks.

tracing resolves each callsite's Interest once, process-globally, then caches it — that is what makes a disabled log statement nearly free. tracing::subscriber::set_default (and the hand-rolled with_recorder in nunciod) installs a subscriber on the current thread only. Under cargo test's parallel harness, a callsite can therefore be evaluated first by a thread with no subscriber installed, cache Interest::never(), and stay silent forever afterwards — including for the test that actually wanted to capture it. The capture buffer comes back empty and the assertion fails.

That predicts exactly what we observe: passes under --test-threads=1, fails in parallel, a different test failing each run depending on scheduling order, and reliable passes in isolation. Measured on this branch: create_rule_handler_logs_domain_event_under_request_scope failed 2 of 6 full-lib runs on a pristine tree, 3 of 3 passing in isolation; a separate outbox log-capture test was made to fail deterministically by draining through a code path a parallel test also touched.

This also explains why the two fixes recorded in #384's commit message measured worse: rebuild_interest_cache() and Interest::sometimes() both fight the cache rather than sidestepping it, and they add global synchronisation that perturbs the very scheduling the failure depends on.

The fix has to either make the subscriber process-global for the test binary — which is what tracing-test does, and what this issue already proposes — or serialise the capturing tests against each other. The workaround used on PR #405 was the third option: restructure the test so it calls the instrumented function directly instead of going through a path a parallel test also exercises. That is a per-test dodge, not a cure.

Affected callsites are wider than nuncio-filter: set_default appears in nuncio-filter/src/engine.rs, nuncio-store/src/db.rs and nuncio-store/src/vault.rs, and nunciod/src/grpc.rs has the same class via its own with_recorder.

This is also why CI on dev has been red continuously since at least 2026-08-01 — four different tests in this family have failed across recent runs, a different one each time.

Mechanism diagnosed while implementing #394 (PR #405), where the same failure was reproduced **deterministically** rather than as a flake — recording it here since it is the same defect class this issue tracks. `tracing` resolves each callsite's `Interest` **once, process-globally**, then caches it — that is what makes a disabled log statement nearly free. `tracing::subscriber::set_default` (and the hand-rolled `with_recorder` in `nunciod`) installs a subscriber on the **current thread only**. Under `cargo test`'s parallel harness, a callsite can therefore be evaluated first by a thread with no subscriber installed, cache `Interest::never()`, and stay silent forever afterwards — including for the test that actually wanted to capture it. The capture buffer comes back empty and the assertion fails. That predicts exactly what we observe: **passes under `--test-threads=1`, fails in parallel**, a different test failing each run depending on scheduling order, and reliable passes in isolation. Measured on this branch: `create_rule_handler_logs_domain_event_under_request_scope` failed 2 of 6 full-lib runs on a pristine tree, 3 of 3 passing in isolation; a separate outbox log-capture test was made to fail **deterministically** by draining through a code path a parallel test also touched. This also explains why the two fixes recorded in #384's commit message measured *worse*: `rebuild_interest_cache()` and `Interest::sometimes()` both fight the cache rather than sidestepping it, and they add global synchronisation that perturbs the very scheduling the failure depends on. The fix has to either make the subscriber process-global for the test binary — which is what `tracing-test` does, and what this issue already proposes — or serialise the capturing tests against each other. The workaround used on PR #405 was the third option: restructure the test so it calls the instrumented function directly instead of going through a path a parallel test also exercises. That is a per-test dodge, not a cure. Affected callsites are wider than `nuncio-filter`: `set_default` appears in `nuncio-filter/src/engine.rs`, `nuncio-store/src/db.rs` and `nuncio-store/src/vault.rs`, and `nunciod/src/grpc.rs` has the same class via its own `with_recorder`. This is also why CI on `dev` has been red continuously since at least 2026-08-01 — four different tests in this family have failed across recent runs, a different one each time.

KofTwentyTwo commented

2026-08-14 22:57:49 +00:00

(Migrated from github.com)

Fixed in #411, merged to dev, though by a different route than this title proposes.

tracing-test was deliberately not adopted: its logs_contain is a substring match, and several of these tests assert on a structured level and field names, which that would have lost. Instead all five test_tracing.rs helpers install the capture layer once as the global default and route events to a per-thread recorder slot, with rebuild_interest_cache() called once at install — never per test.

Root cause, confirmed by instrumentation rather than inference: tracing resolves each callsite's Interest once per process and caches it, while set_default is per-thread. A callsite first executed by a thread with no subscriber caches never and is skipped forever, before any thread-local subscriber is consulted. It reproduces at --test-threads=2 — CI's core count — and is invisible at higher parallelism, which is why dev was red while local runs looked clean.

Measured: RUST_TEST_THREADS=2 cargo test-all went from 3/3 red to 0/8 red; dev CI has been green on every run since.

Fixed in #411, merged to `dev`, though by a different route than this title proposes. `tracing-test` was deliberately **not** adopted: its `logs_contain` is a substring match, and several of these tests assert on a structured level and field names, which that would have lost. Instead all five `test_tracing.rs` helpers install the capture layer **once as the global default** and route events to a per-thread recorder slot, with `rebuild_interest_cache()` called once at install — never per test. Root cause, confirmed by instrumentation rather than inference: `tracing` resolves each callsite's `Interest` once per process and caches it, while `set_default` is per-thread. A callsite first executed by a thread with no subscriber caches `never` and is skipped forever, before any thread-local subscriber is consulted. It reproduces at `--test-threads=2` — CI's core count — and is invisible at higher parallelism, which is why `dev` was red while local runs looked clean. Measured: `RUST_TEST_THREADS=2 cargo test-all` went from 3/3 red to 0/8 red; `dev` CI has been green on every run since.

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: KofTwentyTwo/nuncio#375