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();
}