Problem
test_webhook_queue_scan_skips_and_cleans_damaged_rows in crates/peryx-storage/tests/unit/tests/meta/webhook_tests.rs fails on some runs and not others, and which of its three cases fails varies on an unchanged tree.
The test captures tracing output into a temporary file through a thread-local subscriber, then asserts the cleanup warned once and no more:
let subscriber = tracing_subscriber::fmt().with_writer(Mutex::new(capture.try_clone().unwrap())).finish();
tracing::subscriber::with_default(subscriber, || { /* two scans */ });
...
assert_eq!(output.matches("discarding damaged webhook queue rows").count(), 1);
The failure is always that count reading 0: the warning never reached this case's capture. WebhookQueueCleanup::log emits it on every scan that found damage, so the event was raised and then dropped rather than never raised.
Correction. My first reading of this blamed the process-global max level filter, on the theory that a neighbour leaving its with_default block lowers it under a case still running. That is wrong, and a constructed probe says so: DefaultGuard::drop touches neither the max level nor the interest cache, and a neighbour entering and leaving its block while this thread sits inside its own loses nothing.
The mechanism is the interest cache. A callsite resolves its Interest the first time any thread executes it, and every thread reads that answer afterwards. tracing keeps a has_just_one flag, true whenever at most one dispatcher was alive at the last registration, which is the normal state in a test binary. While it holds, the rebuild consults dispatcher::get_default on the registering thread rather than the registry. A thread holding no subscriber therefore resolves the callsite against NoSubscriber, which yields Interest::never(), and that answer is cached for every thread until some thread constructs a new Dispatch and forces a rebuild over the full registry.
So a case asserting on its capture goes silent whenever a neighbour reaches the callsite first without a subscriber of its own. A per-test subscriber is absent at exactly that moment, and which case loses the race is what varies between runs.
Example
Observed on fix/inbound-throughput-floor-2183, a branch touching none of peryx-storage:
| Run |
Command |
Result |
| 1 |
cargo test --workspace --all-features --lib |
case_1_malformed_timestamp FAILED, left: 0 |
| 2 |
cargo test -p peryx-storage --all-features --lib |
case_2_missing_record FAILED, left: 0 |
| 3-5 |
cargo test -p peryx-storage --all-features --lib -- --test-threads=1 webhook_tests::test_webhook_queue_scan |
3 passed, three times |
Constructed rather than waited for: a thread holding no subscriber executes a fresh callsite and joins, then this thread raises an event at that same callsite while inside its own with_default. The capture comes back empty. Both narrower interleavings, a neighbour entering and a neighbour leaving, capture the event as expected.
A different case failing each time, on identical code, and every serialised run passing, is the overlap rather than the assertion.
Required change
Make the assertion independent of what other tests are doing to the process-global dispatcher. The capture has to belong to the case that asserts on it for the whole time that case is running, whatever else runs beside it.
Serialising the three cases against each other is enough today, since no other test in the crate uses with_default, but a capture that survives a neighbour is the more durable answer and does not break the next time someone captures logs elsewhere.
Do not weaken the assertion. Counting one warning and no more is what proves the second scan found nothing left to clean, which is the behaviour under test.
Acceptance criteria
- The three cases pass under the default parallel harness across repeated runs.
- The assertion still requires one warning and no more across the two scans.
- A test capturing tracing output elsewhere in the crate cannot reintroduce it.
Boundary
The test's capture. Not a change to WebhookQueueCleanup::log, its wording, or when the scan cleans, and not a change to the other webhook tests.
Problem
test_webhook_queue_scan_skips_and_cleans_damaged_rowsincrates/peryx-storage/tests/unit/tests/meta/webhook_tests.rsfails on some runs and not others, and which of its three cases fails varies on an unchanged tree.The test captures tracing output into a temporary file through a thread-local subscriber, then asserts the cleanup warned once and no more:
The failure is always that count reading
0: the warning never reached this case's capture.WebhookQueueCleanup::logemits it on every scan that found damage, so the event was raised and then dropped rather than never raised.Correction. My first reading of this blamed the process-global max level filter, on the theory that a neighbour leaving its
with_defaultblock lowers it under a case still running. That is wrong, and a constructed probe says so:DefaultGuard::droptouches neither the max level nor the interest cache, and a neighbour entering and leaving its block while this thread sits inside its own loses nothing.The mechanism is the interest cache. A callsite resolves its
Interestthe first time any thread executes it, and every thread reads that answer afterwards.tracingkeeps ahas_just_oneflag, true whenever at most one dispatcher was alive at the last registration, which is the normal state in a test binary. While it holds, the rebuild consultsdispatcher::get_defaulton the registering thread rather than the registry. A thread holding no subscriber therefore resolves the callsite againstNoSubscriber, which yieldsInterest::never(), and that answer is cached for every thread until some thread constructs a newDispatchand forces a rebuild over the full registry.So a case asserting on its capture goes silent whenever a neighbour reaches the callsite first without a subscriber of its own. A per-test subscriber is absent at exactly that moment, and which case loses the race is what varies between runs.
Example
Observed on
fix/inbound-throughput-floor-2183, a branch touching none ofperyx-storage:cargo test --workspace --all-features --libcase_1_malformed_timestampFAILED,left: 0cargo test -p peryx-storage --all-features --libcase_2_missing_recordFAILED,left: 0cargo test -p peryx-storage --all-features --lib -- --test-threads=1 webhook_tests::test_webhook_queue_scanConstructed rather than waited for: a thread holding no subscriber executes a fresh callsite and joins, then this thread raises an event at that same callsite while inside its own
with_default. The capture comes back empty. Both narrower interleavings, a neighbour entering and a neighbour leaving, capture the event as expected.A different case failing each time, on identical code, and every serialised run passing, is the overlap rather than the assertion.
Required change
Make the assertion independent of what other tests are doing to the process-global dispatcher. The capture has to belong to the case that asserts on it for the whole time that case is running, whatever else runs beside it.
Serialising the three cases against each other is enough today, since no other test in the crate uses
with_default, but a capture that survives a neighbour is the more durable answer and does not break the next time someone captures logs elsewhere.Do not weaken the assertion. Counting one warning and no more is what proves the second scan found nothing left to clean, which is the behaviour under test.
Acceptance criteria
Boundary
The test's capture. Not a change to
WebhookQueueCleanup::log, its wording, or when the scan cleans, and not a change to the other webhook tests.