Conversation
Shuttle's span bookkeeping called `Span::current()` from inside
`tracing::dispatcher::get_default`. `get_default` marks the thread's
dispatcher state as in use for the duration of its callback, and while any
thread in the process holds a scoped default subscriber, a nested
`Span::current()` then returns `Span::none()`, even on a thread that never
touched its own default.
In `exit_task_span` that made the loop that exits the task's spans exit
nothing, while the unconditional enter of `top_level_span` still ran, so
every scheduling step leaked one entry on the thread's entered-span stack.
Once the leaked spans' handles were dropped the entries pointed at closed
spans, and a later `Span::current()` resolved to one of them and panicked
with "tried to clone a span that already closed".
This is the intermittent full-suite failure that hit a different test each
run. The tests in basic::{tag,task,metrics,labels} install a thread-scoped
default with `tracing::subscriber::set_default`, and whichever test was
mid-execution on another thread while one of them held it was the one to
panic. That is also why it never reproduced with --test-threads=1, in
isolation, or with any instrumentation on Shuttle's own hot path.
Route every exit and enter through `Span::with_subscriber`, which hands
over the span's own dispatcher without going through `get_default`, in all
three places that did this: `exit_task_span`, `enter_task_span`, and
`ResetSpanOnDrop`. The last one leaked one entry per `Runner::run`. The
one in `enter_task_span` cannot currently leak, because it only runs after
`exit_task_span` has drained the stack, and is changed for consistency.
The regression test holds a scoped default on another thread, enters a
span around a Shuttle run and another inside it across a context switch,
and checks that no entries leak, that the inner span survives the switch,
and that the caller's span is current again afterwards. On the unfixed
code it reports 290 leaked entries; reverting only the `exit_task_span`
hunk leaks 102, and reverting only the `ResetSpanOnDrop` hunk leaks 1.
Full suite: 20 of 20 runs clean with the fix, against roughly one run in
four to six failing before. Skipping the four set_default modules on the
unfixed code gave 16 of 16 clean runs.
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.
Fixes the intermittent full-suite failure that hits a different test each run:
It is independent of #352 and #353 and branches from
main.Root cause
Shuttle's span bookkeeping called
Span::current()from insidetracing::dispatcher::get_default:get_defaultmarks the thread's dispatcher state as in use while its callback runs. Whenever any thread in the process holds a scoped default subscriber, aSpan::current()nested inside that callback returnsSpan::none(). That happens even on a thread that never set a default of its own. Standalone, with nothing from Shuttle involved:So in
exit_task_spanthe drain loop exits nothing, but the unconditionalenter(top_level_span)still runs. Each scheduling step leaks one entry on the thread's entered-span stack. After those spans' handles drop, the entries point at closed spans, and the nextSpan::current()that resolves to one of them panics inclone_span.The scoped defaults come from the tests themselves.
basic::{tag, task, metrics, labels}install one withtracing::subscriber::set_default, and the victim is whichever test is mid-execution on another thread at that moment.Evidence
I captured one failure with a locally patched
tracing-subscriber. It journals every entered-span-stack mutation and refcount change inside the subscriber, so Shuttle's own code wasn't touched. Every earlier attempt that instrumented Shuttle's hot path hid the bug completely. At the moment of the panic, the failing thread's entered-span stack was ~96 deep, made mostly of repeatedduplicatepushes of the sameexecutionspan id (one id appeared ~55 times), and every entry pointed at an already-freed span. The id being cloned belonged to a closednew_taskspan.Why every standard way of isolating it failed:
--test-threads=1set_defaultmodulesFix
Every exit and enter now goes through
Span::with_subscriber, which hands over the span's own dispatcher without callingget_default. There were three sites:exit_task_span: the flake. Leaked one entry per scheduling step.ResetSpanOnDrop::drop: leaked one entry perRunner::run. This site is not the flake, but the leak is real and accumulates on test threads.enter_task_span: same pattern, but I could not make it leak. It only runs right afterexit_task_spanhas drained the stack, so it has exactly one span to exit. Changed for consistency, not as a tested fix.Regression test
basic::tracing::span_bookkeeping_with_scoped_default_on_another_threadholds a scoped default on another thread. It enters one span around a Shuttle run and another inside it, across a context switch, and asserts three things: no entries leak, the inner span is still current after the switch, and the caller's span is current again after the run.I checked that the test catches each leaking site independently:
mainexit_task_spanhunk revertedResetSpanOnDrophunk revertedOn
mainthis is a correctness problem, not only leftover state. In a probe run, the span a user entered before a context switch was no longer current after it, and the caller's own span was not current aftercheck_randomreturned.Testing
cargo fmt --check,cargo clippy --workspace --all-targets,cargo doccleancargo test --release -p shuttle: 427 passed, 0 failed (the 426 existing tests plus the new one)#[ignore]d tracing tests (test_tracing_nested_spans,instrumented_futures,test_stacks_cleaned_on_panic) pass with--include-ignored. I haven't un-ignored them here, since their comment gives separate reasons.By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.