Opentelemetry panics on Span::follows_from with "Span to follow not found"

[SebastiaanYN]

Bug Report

Version

tracing-playground v0.1.0 (/Users/sebastiaan/x/tracing-playground)
├── tracing v0.1.37
│   ├── tracing-attributes v0.1.23 (proc-macro)
│   └── tracing-core v0.1.30
├── tracing-opentelemetry v0.18.0
│   ├── tracing v0.1.37 (*)
│   ├── tracing-core v0.1.30 (*)
│   ├── tracing-log v0.1.3
│   │   └── tracing-core v0.1.30 (*)
│   └── tracing-subscriber v0.3.16
│       ├── tracing-core v0.1.30 (*)
│       └── tracing-log v0.1.3 (*)
└── tracing-subscriber v0.3.16 (*)

Platform

Darwin C02G3240ML7J 21.6.0 Darwin Kernel Version 21.6.0: Mon Aug 22 20:17:10 PDT 2022; root:xnu-8020.140.49~2/RELEASE_X86_64 x86_64

Crates

tracing-opentelemetry

Description

Using this code:

use opentelemetry::global;
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
    global::set_text_map_propagator(opentelemetry_jaeger::Propagator::new());
    let tracer = opentelemetry_jaeger::new_agent_pipeline()
        .with_service_name("test")
        .install_simple()
        .unwrap();
    let opentelemetry = tracing_opentelemetry::layer().with_tracer(tracer);

    tracing_subscriber::registry()
        .with(opentelemetry)
        .with(fmt::Layer::default())
        .try_init()
        .unwrap();

    tracing::trace_span!("start").in_scope(|| {
        let span1 = tracing::span!(tracing::Level::INFO, "span_1");
        let span2 = tracing::span!(tracing::Level::DEBUG, "span_2");
        span2.follows_from(span1);
    });

    opentelemetry::global::shutdown_tracer_provider();
}

Causes this panic to occur:

thread 'main' panicked at 'Span to follow not found, this is a bug', /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-opentelemetry-0.18.0/src/layer.rs:779:14
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'Mutex poisoned: PoisonError { .. }', /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/registry/sharded.rs:437:58
stack backtrace:
   0:        0x1089d30b2 - std::backtrace_rs::backtrace::libunwind::trace::h3274e49b4ebf7e53
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x1089d30b2 - std::backtrace_rs::backtrace::trace_unsynchronized::hd211d632c7624604
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x1089d30b2 - std::sys_common::backtrace::_print_fmt::h1e774fa26a8ee490
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:66:5
   3:        0x1089d30b2 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hd2e8cbde22b780fc
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:45:22
   4:        0x1089ee7ba - core::fmt::write::hd6692086cdd356a7
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/fmt/mod.rs:1202:17
   5:        0x1089ce72c - std::io::Write::write_fmt::h6043124a2486acbb
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/io/mod.rs:1679:15
   6:        0x1089d46fb - std::sys_common::backtrace::_print::h3d78a31fac988d9b
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:48:5
   7:        0x1089d46fb - std::sys_common::backtrace::print::hdfd67a42b253a0c5
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:35:9
   8:        0x1089d46fb - std::panicking::default_hook::{{closure}}::h87a12b8b06887dd7
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:295:22
   9:        0x1089d4407 - std::panicking::default_hook::h7f68dad17e0bfaa4
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:314:9
  10:        0x1089d4d1f - std::panicking::rust_panic_with_hook::hd57427cbbfc3717a
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:698:17
  11:        0x1089d4c63 - std::panicking::begin_panic_handler::{{closure}}::h33aab6d04e2bba70
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:588:13
  12:        0x1089d3548 - std::sys_common::backtrace::__rust_end_short_backtrace::h0e7a76f927db9964
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:138:18
  13:        0x1089d492d - rust_begin_unwind
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:584:5
  14:        0x1089fc653 - core::panicking::panic_fmt::hcf6f3c517c6f3cb3
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/panicking.rs:142:14
  15:        0x1089fc7b5 - core::result::unwrap_failed::ha988429942445917
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/result.rs:1785:5
  16:        0x10888d184 - core::result::Result<T,E>::expect::h0a8d890089558303
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/result.rs:1064:23
  17:        0x108893b22 - <tracing_subscriber::registry::sharded::Data as tracing_subscriber::registry::SpanData>::extensions_mut::h443c0bc5790d5ca6
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/registry/sharded.rs:437:28
  18:        0x108889535 - tracing_subscriber::registry::SpanRef<R>::extensions_mut::h60f0e9f46b850b99
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/registry/mod.rs:492:9
  19:        0x10881fdb7 - <tracing_opentelemetry::layer::OpenTelemetryLayer<S,T> as tracing_subscriber::layer::Layer<S>>::on_close::ha816aaed760d9706
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-opentelemetry-0.18.0/src/layer.rs:900:30
  20:        0x10881d340 - <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::try_close::h65abeb4f56252d81
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/layer/layered.rs:196:13
  21:        0x10881d40d - <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::try_close::h86982736d3f74242
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.3.16/src/layer/layered.rs:186:12
  22:        0x1088d3603 - <alloc::sync::Arc<S> as tracing_core::subscriber::Subscriber>::try_close::h956e33048c899124
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/subscriber.rs:848:9
  23:        0x1088d7cf5 - tracing_core::dispatcher::Dispatch::try_close::hbd59b60bbe93b7e3
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/dispatcher.rs:676:9
  24:        0x108875ea8 - <tracing::span::Span as core::ops::drop::Drop>::drop::h55a46e973fc50ced
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-0.1.37/src/span.rs:1463:13
  25:        0x108875ea8 - core::ptr::drop_in_place<tracing::span::Span>::h81556811314bb622
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/ptr/mod.rs:487:1
  26:        0x1088298b8 - tracing_playground::main::{{closure}}::ha20a9f4f953f757b
                               at /Users/sebastiaan/x/tracing-playground/src/main.rs:22:5
  27:        0x1088273ac - tracing::span::Span::in_scope::h51afe69342a0c59e
                               at /Users/sebastiaan/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-0.1.37/src/span.rs:1102:9
  28:        0x108818db0 - tracing_playground::main::hafb338265237df03
                               at /Users/sebastiaan/x/tracing-playground/src/main.rs:18:5
  29:        0x10881b83e - core::ops::function::FnOnce::call_once::hf66ac070a31988d8
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/ops/function.rs:248:5
  30:        0x10881b221 - std::sys_common::backtrace::__rust_begin_short_backtrace::h3719f43180ee6bdf
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/sys_common/backtrace.rs:122:18
  31:        0x108819f24 - std::rt::lang_start::{{closure}}::h195fb9cb358d3f58
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/rt.rs:166:18
  32:        0x1089cbe7e - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hb30f3c124d6422bd
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/core/src/ops/function.rs:283:13
  33:        0x1089cbe7e - std::panicking::try::do_call::h6ab65f1fbf11caa5
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:492:40
  34:        0x1089cbe7e - std::panicking::try::hb963b3a8541f11db
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:456:19
  35:        0x1089cbe7e - std::panic::catch_unwind::hd044952603e5f56c
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panic.rs:137:14
  36:        0x1089cbe7e - std::rt::lang_start_internal::{{closure}}::h3a2dc7ba533401e5
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/rt.rs:148:48
  37:        0x1089cbe7e - std::panicking::try::do_call::h88480942a6edc3bf
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:492:40
  38:        0x1089cbe7e - std::panicking::try::ha84f131c957dae86
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panicking.rs:456:19
  39:        0x1089cbe7e - std::panic::catch_unwind::hab613c35aec6b94f
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/panic.rs:137:14
  40:        0x1089cbe7e - std::rt::lang_start_internal::ha5deaf08dab8765b
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/rt.rs:148:20
  41:        0x108819ef7 - std::rt::lang_start::ha8b9ef3ca25e4fe5
                               at /rustc/897e37553bba8b42751c67658967889d11ecd120/library/std/src/rt.rs:165:17
  42:        0x108818ebb - _main
thread panicked while panicking. aborting.
[1]    77721 abort      cargo run

[ghost]

I'm not sure if this is correct, but I'm pretty sure you need to enter the spans first. Creating them does nothing until you enter them, and then they are "used".

[SebastiaanYN]

I'm not sure if this is correct, but I'm pretty sure you need to enter the spans first. Creating them does nothing until you enter them, and then they are "used".

That's not possible as entering the span takes ownership of it, so you can't call follows_from afterwards.

I did find that it's possible to add the link through opentelemetry directly by getting the context from the span as a temporary workaround.

let span1 = tracing::span!(tracing::Level::INFO, "span_1");
let span2 = tracing::span!(tracing::Level::DEBUG, "span_2");

{
    let cx = span1.context();
    let span = cx.span();
    let span_cx = span.span_context();
    span2.add_link(span_cx.clone());
}

[ghost]

Does this work? Here we get the ID and then enter the span. The ID should still stay valid:

let span1 = tracing::span!(tracing::Level::INFO, "span_1");
let span1_id = span1.id();
let span1=span1.entered(); // Enter here, ID should still be valid
let span2 = tracing::span!(tracing::Level::DEBUG, "span_2");
span2.follows_from(span1_id);

[SebastiaanYN]

That does indeed work, thanks. Still interesting that you'd need to enter them first.

[ghost]

You're welcome :)

[mladedav]

You don't need to enter the span, it just needs to exist. This is a special case of #688.

When you have a span entered, you can guarantee that it exists so that's one way to go about it. Doing this will also work:

    tracing::trace_span!("start").in_scope(|| {
        let span1 = tracing::span!(tracing::Level::INFO, "span_1");
        let span2 = tracing::span!(tracing::Level::DEBUG, "span_2");
        span2.follows_from(span1.clone());
    });