Opentelemetry tracer not working as global default

[dvdsk]

Bug Report

I like to put logging/tracing code in a separate setup_tracing function. This works fine with the tracing_subscriber::fmt tracer however it does not work with the tracing_opentelemetry tracer. I tried both the opentelemetry_jaeger and stdout exporters.

Version

tracing-min-example v0.1.0 
│   │       │   │   └── tracing v0.1.26
│   │       │   │       └── tracing-core v0.1.19
│   │       │   ├── tracing v0.1.26 (*)
├── tracing v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c)
│   ├── tracing-attributes v0.2.0 (proc-macro) (https://github.com/tokio-rs/tracing#57fca59c)
│   └── tracing-core v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c)
├── tracing-opentelemetry v0.15.0 (https://github.com/tokio-rs/tracing#57fca59c)
│   ├── tracing v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│   ├── tracing-core v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│   ├── tracing-log v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c)
│   │   └── tracing-core v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│   └── tracing-subscriber v0.3.0 (https://github.com/tokio-rs/tracing#57fca59c)
│       ├── tracing v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│       ├── tracing-core v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│       ├── tracing-log v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
│       └── tracing-serde v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c)
│           └── tracing-core v0.2.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)
└── tracing-subscriber v0.3.0 (https://github.com/tokio-rs/tracing#57fca59c) (*)

Platform

Linux david-main 5.11.0-31-generic #33-Ubuntu SMP Wed Aug 11 13:19:04 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Crates

tracing-opentelemetry

Description

I made a minimal example to illustrate the issue: https://github.com/dskleingeld/tracing-min-exampl/blob/main/src/main.rs

When you run this the fmt subscriber prints to stdout: "hello from setup" and "hello main after setup ran". The opentelemetry tracer prints span data once containing only "hello from setup".

Hello, world!
�[2mAug 30 14:20:55.280�[0m �[32m INFO�[0m �[1min setup�[0m: hello from setup
�[2mAug 30 14:20:55.280�[0m �[32m INFO�[0m �[1mafter setup�[0m: hello from main after setup ran
SpanData { span_context: SpanContext { trace_id: TraceId(236482382998336947167595217718168329784), span_id: SpanId(9604849260417992282), trace_flags: TraceFlags(1), is_remote: false, trace_state: TraceState(None) }, parent_span_id: SpanId(0), span_kind: Internal, name: "in setup", start_time: SystemTime { tv_sec: 1630326055, tv_nsec: 279916561 }, end_time: SystemTime { tv_sec: 1630326055, tv_nsec: 280162235 }, attributes: EvictedHashMap { map: {Key("code.namespace"): String("tracing_min_example"), Key("code.filepath"): String("src/main.rs"), Key("code.lineno"): I64(24), Key("busy_ns"): I64(138443), Key("idle_ns"): I64(105818)}, evict_list: [Key("idle_ns"), Key("busy_ns"), Key("code.lineno"), Key("code.namespace"), Key("code.filepath")], max_len: 128, dropped_count: 0 }, events: EvictedQueue { queue: Some([Event { name: "hello from setup", timestamp: SystemTime { tv_sec: 1630326055, tv_nsec: 280133930 }, attributes: [KeyValue { key: Key("level"), value: String("INFO") }, KeyValue { key: Key("target"), value: String("tracing_min_example") }], dropped_attributes_count: 0 }]), max_len: 128, dropped_count: 0 }, links: EvictedQueue { queue: None, max_len: 128, dropped_count: 0 }, status_code: Unset, status_message: "", resource: Some(Resource { attrs: {Key("service.name"): String("unknown_service")} }), instrumentation_lib: InstrumentationLibrary { name: "opentelemetry", version: Some("0.16.0") } }

[jtescher]

@dskleingeld what is happening in this case is that the after setup root span is not being dropped until the program exists so it is never reported to opentelemetry.

You can see the results you are expecting if drop the span earlier:

fn main() {
    println!("Hello, world!");
    setup_tracing();
    {
        let root = span!(tracing::Level::INFO, "after setup");
        let _enter = root.enter();
        info!("hello from main after setup ran");
    }

    opentelemetry::global::shutdown_tracer_provider(); // sending remaining spans
}

output:

Sep 11 20:28:29.069  INFO in setup: hello from setup
Sep 11 20:28:29.070  INFO after setup: hello from main after setup ran
SpanData { span_context: SpanContext { trace_id: TraceId(334283099000773540319038056516333361399), span_id: SpanId(2447663840352814301), trace_flags: TraceFlags(1), is_remote: false, trace_state: TraceState(None) }, parent_span_id: SpanId(0), span_kind: Internal, name: "in setup", start_time: SystemTime { tv_sec: 1631406509, tv_nsec: 69493000 }, end_time: SystemTime { tv_sec: 1631406509, tv_nsec: 70099000 }, attributes: EvictedHashMap { map: {Key("idle_ns"): I64(104029), Key("busy_ns"): I64(510479), Key("code.filepath"): String("src/main.rs"), Key("code.namespace"): String("tracing_min_example"), Key("code.lineno"): I64(24)}, evict_list: [Key("idle_ns"), Key("busy_ns"), Key("code.lineno"), Key("code.namespace"), Key("code.filepath")], max_len: 128, dropped_count: 0 }, events: EvictedQueue { queue: Some([Event { name: "hello from setup", timestamp: SystemTime { tv_sec: 1631406509, tv_nsec: 70075000 }, attributes: [KeyValue { key: Key("level"), value: String("INFO") }, KeyValue { key: Key("target"), value: String("tracing_min_example") }], dropped_attributes_count: 0 }]), max_len: 128, dropped_count: 0 }, links: EvictedQueue { queue: None, max_len: 128, dropped_count: 0 }, status_code: Unset, status_message: "", resource: Some(Resource { attrs: {Key("service.name"): String("unknown_service")} }), instrumentation_lib: InstrumentationLibrary { name: "opentelemetry", version: Some("0.16.0") } }
SpanData { span_context: SpanContext { trace_id: TraceId(183984860696800110655224596740358480455), span_id: SpanId(13578162754968181933), trace_flags: TraceFlags(1), is_remote: false, trace_state: TraceState(None) }, parent_span_id: SpanId(0), span_kind: Internal, name: "after setup", start_time: SystemTime { tv_sec: 1631406509, tv_nsec: 70193000 }, end_time: SystemTime { tv_sec: 1631406509, tv_nsec: 70255000 }, attributes: EvictedHashMap { map: {Key("busy_ns"): I64(48289), Key("idle_ns"): I64(10354), Key("code.lineno"): I64(32), Key("code.filepath"): String("src/main.rs"), Key("code.namespace"): String("tracing_min_example")}, evict_list: [Key("idle_ns"), Key("busy_ns"), Key("code.lineno"), Key("code.namespace"), Key("code.filepath")], max_len: 128, dropped_count: 0 }, events: EvictedQueue { queue: Some([Event { name: "hello from main after setup ran", timestamp: SystemTime { tv_sec: 1631406509, tv_nsec: 70242000 }, attributes: [KeyValue { key: Key("level"), value: String("INFO") }, KeyValue { key: Key("target"), value: String("tracing_min_example") }], dropped_attributes_count: 0 }]), max_len: 128, dropped_count: 0 }, links: EvictedQueue { queue: None, max_len: 128, dropped_count: 0 }, status_code: Unset, status_message: "", resource: Some(Resource { attrs: {Key("service.name"): String("unknown_service")} }), instrumentation_lib: InstrumentationLibrary { name: "opentelemetry", version: Some("0.16.0") } }