Mutex::new with tracing feature enabled can prevent spans from closing

[xuorig]

Version

tokio = { version = "1.32.0", features = ["full", "rt-multi-thread", "tracing"] }
tracing = "0.1.37"
tracing-subscriber = "0.3.17"

Description

I've been investigating an issue with some traces not getting closed in another repository and tracked it down to a tokio::sync::Mutex (with tracing feature enabled).

If a Mutex is created within the context of a particular parent trace, and then stored in memory to be reused in the context of other traces, it seems like that first parent span will never be closed, since the Mutex and its inner resource_span holds a "reference" (incremented the ref_count of the trace) to the parent span. (This is while using tracing-subscriber as well).

Here's a simple repro, of this "issue", if this is indeed an issue.

#[tokio::main]
async fn main() {
    let subscriber = fmt()
        .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE)
        .with_max_level(Level::TRACE)
        .finish();

    let _ = set_global_default(subscriber.into());

    let span = info_span!("example");
    let guard = span.enter();

    let _mutex = Mutex::new(String::from("hello"));

    drop(guard); // exit guard
    drop(span); // exit span
    eprintln!("Dropped the span... expected the span to be closed now.");

    eprintln!("Dropping the mutex, we should see the span getting closed now.");
}

I chatted briefly about this with @davidbarsky, who mentioned the following:

tokio::sync::Mutex::new() should consider the current, request-level span not as a parent, but rather, as a follows_from-style relationship with a None parent (e.g., span!(parent: None, Level::INFO, "mutex_span");).

From our usage, this seems to ring true. We have a request span that caches a mutex item for a particular request shape, and this trace remains open until the cache is cleared.

I'd be happy to submit a PR if this makes sense to you folks as well.

[davidbarsky]

as a note, I think that this span is the one that needs to be changed.

(an alternative that I drafted, but didn't send, would be to expose a separate constructor that accepts a span as an argument, but that defeats a large purpose of how tracing is designed.)

[xuorig]

It is indeed this span 👍 The other one gets exited and dropped within the in_scope, but this one gets stored on the mutex itself.

I'll note that this issue isn't necessarily particular to Mutex and can happen frequently with libraries that would for example spawn a longer running task. (I happened to find another issue with hyper's IdleTask which kept traces open as well). I'm wondering if spawn should use follows_from as well, or have an API that allows this.

[davidbarsky]

It is indeed this span 👍 The other one gets exited and dropped within the in_scope, but this one gets stored on the mutex itself.

Note that the in_scope call is the same span, but essential bit (the parent/child/follows_from relationship) is set on the line I linked to. in_scope is morally equivalent to a Span::enter call, but with a more explicit scope.

I'll note that this issue isn't necessarily particular to Mutex and can happen frequently with libraries that would for example spawn a longer running task. (I happened to find another issue with hyper's IdleTask which kept traces open as well). I'm wondering if spawn should use follows_from as well, or have an API that allows this.

spawn is a bit more complicated than a Mutex because I've seen usages of it where people do want a parent/child relationship from the calling scope. spawn (or a builder option on Task) might need to instead accept a span as an argument, but I'm not really sure how to solve this at the moment.

At the very least, I'm pretty confident that a PR to RwLock/Mutex along the lines of what was discussed here is warranted. We can figure something out with spawn later.

[xuorig]

Note that the in_scope call is the same span, but essential bit (the parent/child/follows_from relationship) is set on the line I linked to. in_scope is morally equivalent to a Span::enter call, but with a more explicit scope.

Yes 💯 , I was referring to this thinking this was another span, but this is a trace event. 🙈