Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
SebastiaanYN opened this issue Nov 28, 2022 · 6 comments

Comments

@SebastiaanYN
Copy link

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
Copy link

ghost commented Jan 3, 2023

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
Copy link
Author

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
Copy link

ghost commented Jan 4, 2023

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
Copy link
Author

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

@ghost
Copy link

ghost commented Jan 5, 2023

You're welcome :)

fnichol added a commit to systeminit/si that referenced this issue Jan 26, 2024
This change incorporates an upstream fix in `tracing-opentelemetry` to
prevent parent and "follows-from" span association from panicking under
certain scenarios.

Additionally, the strategy to determine the appropriate span for
PostgreSQL and NATS transactions/subscriptions has been updated
slightly. The macros present prior to this change attempted to prevent
another "Mutex poisoned" issue encountered a year ago. The updated
`tx_span()` and `sub_span()` functions check to see if `Span::current()`
is disabled, in which case a `Span::none()` is returned, otherwise the
current Span is returned. The former macros were slightly less flexible
in that they checked `target` and `level` span metadata--which happened
to be correct in these two cases.

References: tokio-rs/tracing-opentelemetry#14
References: tokio-rs/tracing-opentelemetry#86
References: tokio-rs/tracing#2399
References: tokio-rs/tracing#1766

Signed-off-by: Fletcher Nichol <fletcher@systeminit.com>
fnichol added a commit to systeminit/si that referenced this issue Jan 26, 2024
This change incorporates an upstream fix in `tracing-opentelemetry` to
prevent parent and "follows-from" span association from panicking under
certain scenarios.

Additionally, the strategy to determine the appropriate span for
PostgreSQL and NATS transactions/subscriptions has been updated
slightly. The macros present prior to this change attempted to prevent
another "Mutex poisoned" issue encountered a year ago. The updated
`tx_span()` and `sub_span()` functions check to see if `Span::current()`
is disabled, in which case a `Span::none()` is returned, otherwise the
current Span is returned. The former macros were slightly less flexible
in that they checked `target` and `level` span metadata--which happened
to be correct in these two cases.

References: tokio-rs/tracing-opentelemetry#14
References: tokio-rs/tracing-opentelemetry#86
References: tokio-rs/tracing#2399
References: tokio-rs/tracing#1766

Signed-off-by: Fletcher Nichol <fletcher@systeminit.com>
si-bors-ng bot added a commit to systeminit/si that referenced this issue Jan 26, 2024
3222: chore(si-data-pg,si-data-nats): compute appropriate Span for txns/subs r=fnichol a=fnichol

This change incorporates an upstream fix in `tracing-opentelemetry` to prevent parent and "follows-from" span association from panicking under certain scenarios.

Additionally, the strategy to determine the appropriate span for PostgreSQL and NATS transactions/subscriptions has been updated slightly. The macros present prior to this change attempted to prevent another "Mutex poisoned" issue encountered a year ago. The updated `tx_span()` and `sub_span()` functions check to see if `Span::current()` is disabled, in which case a `Span::none()` is returned, otherwise the current Span is returned. The former macros were slightly less flexible in that they checked `target` and `level` span metadata--which happened to be correct in these two cases.

References: tokio-rs/tracing-opentelemetry#14
References: tokio-rs/tracing-opentelemetry#86
References: tokio-rs/tracing#2399
References: tokio-rs/tracing#1766

Co-authored-by: Fletcher Nichol <fletcher@systeminit.com>
@mladedav
Copy link
Contributor

mladedav commented Jun 13, 2024

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants