TraceProvider::with_exporter immediately drops BatchSpanProcessor

[frigus02]

While testing #224, I came across an issue.

Steps to reproduce

1. Checkout the PR (at the point of writing ffa96df).
2. Open examples/stdout.rs and change:

   + #[tokio::main]
   + async fn main() {
   - fn main() {

3. Run cargo run --example stdout and observe the span being printed to the console.
4. Run cargo run --example stdout --features tokio and observe that nothing is printed. With the tokio feature enabled it used the BatchSpanProcessor setup by TraceProvider::with_exporter.

Analysis

I reproduced it on master as well and with a few print statements found that the BatchSpanProcessorWorker is immediately dropped after calling with_exporter.

See my experiments here: 13fc775

The reason is that with_exporter uses either tokio::task::spawn_blocking or async_std::task::spawn_blocking (see sdk::TraceProvider). Both of those expect a blocking function, not a function returning a future. This means the BatchSpanProcessorWorker is never polled.

Possible solution

I assume the reason for using spawn_blocking is that the exporters currently run blocking, so it's good to run on a special thread for blocking work. The solution for the problem then is most likely to execute the future using block_on:

let spawn = |future| {
    tokio::task::spawn_blocking(|| {
        futures::executor::block_on(future);
        // or tokio::runtime::Handle::current().block_on(future)
        // or async_std::task::block_on(future)
    })
};
let batch = sdk::BatchSpanProcessor::builder(exporter, spawn, async_std::stream::interval);

If I do this, however, the program never exits. You can test this with the above linked example. The BatchSpanProcessorWorker just keeps running because it does never receive a shotdown message.

I'm not sure why, yet. I think the provider should be dropped and then notify all registered span processors. But that does not seem to happen.

If I manually call shutdown for all span processors, the worker stops properly, exports the remaining spans, and then the program exits.

I'm happy to work on a fix, but I would like to hear your thoughts first. What's the best way to proceed here?

[frigus02]

I think the provider should be dropped and then notify all registered span processors.

I'm pretty sure this happens because:

• A TraceProvider stores its data in an inner struct inside an Arc.
• We call shutdown for all span processors when this inner struct is dropped.
• The inner struct owns a list of named Tracers.
• Each Tracer owns a TraceProvider, which now forms a loop.
• We never drop named tracers, so there is always going to be a strong reference to the inner struct of the provider.

The easiest fix here might be not storing named tracers at all. I think there are only a very small number of allocations for a new tracer. So that might be fine.

There is an additional reference to the provider in global as well. I have no idea how to solve this. Maybe we need another mechanism for calling shutdown, or maybe we need something like global::unset_provider().

[jtescher]

@frigus02 good catch, looks like we may need to go with something more along the lines of:

let spawn = |future| std::thread::spawn(|| futures::executor::block_on(future))

Although giving the thread a name would be nice too for debugging

[frigus02]

I tested using std::thread::spawn. Results:

• It executes the BatchSpanProcessorWorker correctly
• It does not automatically wait for the thread to finish, which leads to a panic when using the stdout exporter:

  thread '<unnamed>' panicked at 'timer error: the timer is shutdown, must be called from the context of Tokio runtime
  

So in a way usig spawn_blocking is nice, because it plays nicely with the tokio/async_std runtime.

Can you think of a nice way to solve shutdown not being called at the moment because of the references?

[frigus02]

Can you think of a nice way to solve shutdown not being called at the moment because of the references?

#[tokio::main]
async fn main() {
    let pipeline = stdout::new_pipeline().install();
    pipeline.tracer.in_span("test", |cx| {});

    drop(pipeline); // Dropping the pipeline could unregister the global provider, freeing up the reference.
}

Or maybe it's better to be explicit:

#[tokio::main]
async fn main() {
    let (tracer, uninstall) = stdout::new_pipeline().install();
    tracer.in_span("test", |cx| {});

    uninstall(); // Calling uninstall could unregister the global provider and clear named tracer, freeing up all references.
}

[jtescher]

@frigus02 yeah combination of drop guard, and having tracers have weak references to tracer providers should make things better.