Missing events when using tracing-opentelemetry with threads

[bjchambers]

Bug Report

Version

tracing-repro v0.1.0-dev (/Users/ben/kaskada/tracing-repro)
│       │   └── tracing v0.1.29
│       │       ├── tracing-attributes v0.1.18 (proc-macro)
│       │       └── tracing-core v0.1.21
│       │   ├── tracing v0.1.29 (*)
│       │   └── tracing v0.1.29 (*)
│       ├── tracing v0.1.29 (*)
│       └── tracing-futures v0.2.5
│           └── tracing v0.1.29 (*)
│   ├── tracing v0.1.29 (*)
│   └── tracing-futures v0.2.5 (*)
├── tracing v0.1.29 (*)
├── tracing-opentelemetry v0.16.0
│   ├── tracing v0.1.29 (*)
│   ├── tracing-core v0.1.21 (*)
│   ├── tracing-log v0.1.2
│   │   └── tracing-core v0.1.21 (*)
│   └── tracing-subscriber v0.3.6
│       ├── tracing v0.1.29 (*)
│       ├── tracing-core v0.1.21 (*)
│       ├── tracing-log v0.1.2 (*)
│       └── tracing-serde v0.1.2
│           └── tracing-core v0.1.21 (*)
├── tracing-serde v0.1.2 (*)
└── tracing-subscriber v0.3.6 (*)

Platform

OS X

Description

I have a project that uses some async and some threads. I've observed a few problematic behaviors, including (a) traces being truncated and (b) spans not having a trace ID when I try to include it while logging (as described in #1531).

I attempted to distill a repro by using the stdout tracer, removing logging entirely (as well as the inclusion of trace IDs), and have found what looks like a bug -- when starting a new thread, events in the immediate first span are not traced (they are logged if I use a standard logging subscriber), and if I create a span within that it gets a new trace ID rather than being part of the current trace.

I've also tried explicitly passing the parent in, explicitly getting the current context and re-attaching it within the thread, etc. and haven't been able to find a way to get the spans within the thread properly associated.

Code is shown below -- I expected to see the event THIS EVENT DOES NOT SHOW UP in the output, but did not.

use tracing::{info, info_span, Instrument};
use tracing_opentelemetry::OpenTelemetryLayer;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;

fn create_tracer<T>() -> OpenTelemetryLayer<T, opentelemetry::sdk::trace::Tracer>
where
    T: tracing::Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span>,
{
    let tracer = opentelemetry::sdk::export::trace::stdout::new_pipeline()
        .with_pretty_print(true)
        .install_simple();

    tracing_opentelemetry::layer().with_tracer(tracer)
}

pub fn setup_tracing() {
    tracing_subscriber::registry()
        .with(create_tracer())
        // .with(log) disable logging for repro
        .try_init()
        .unwrap();
}

#[tokio::main]
async fn main() {
    setup_tracing();

    {
        let _span = info_span!("main").entered();
        some_fn().in_current_span().await;
    }

    opentelemetry::global::force_flush_tracer_provider();
}

#[tracing::instrument]
async fn some_fn() {
    info!("In some_fn");

    let span = info_span!("Inner span");

    // Also tried passing the parent in.
    // let parent = tracing::Span::current();

    let thread = std::thread::spawn(move || {
        let _ = span.enter();
        // let _ = info_span!(parent: &parent, "Inner span").entered();

        info!("THIS EVENT DOES NOT SHOW UP");

        let _enter2 = info_span!("Nested span").entered();
        info!("In nested_span");
    });
    thread.join().unwrap();
}

[davidbarsky]

Sorry for the delay in responding. First things first: I don't recommend spawning a thread inside an async function; I would do this outside of that context or use tokio::task::spawn_blocking if benchmarks indicate that it's worthwhile to use. Freely spawning threads inside of a Tokio context (or any other futures executor) risks blocking the thread by not allowing the task to suspend, leading to worse performance.

I'm able to get the event with the message "THIS EVENT DOES NOT SHOW UP" with the following code:

#[tracing::instrument]
fn some_fn() {
    info!("In some_fn");

    let span = info_span!("Inner span");

    let thread = std::thread::spawn(move || {
        let _span = span.entered();
        // let _ = info_span!(parent: &parent, "Inner span").entered();

        info!("THIS EVENT DOES NOT SHOW UP");

        let _enter2 = info_span!("Nested span").entered();
        info!("In nested_span");
    });
    thread.join().unwrap();
}

There are two contributing factors that explain what's happening here:

• Inside of the thread::spawn, the span is dropped immediately after you enter it because it is assigned to _. To keep it from being dropped until the end of the scope, you must give it a non-_ name.
• tracing-opentelemetry's Layer will not record events that are outside of a span. If this isn't documented, this should be.