Logging a struct holding a SpanTrace causes a core dump if using OpenTelemetryLayer

[LukeMathWalker]

Bug Report

Version

tracing-min v0.1.0 (/home/luca/Documents/code/tracing-min)
├── tracing v0.1.15
│   ├── tracing-attributes v0.1.8
│   └── tracing-core v0.1.10
├── tracing-error v0.1.2
│   ├── tracing v0.1.15 (*)
│   └── tracing-subscriber v0.2.6
│       ├── tracing-core v0.1.10 (*)
│       ├── tracing-log v0.1.1
│       │   └── tracing-core v0.1.10 (*)
│       └── tracing-serde v0.1.1
│           └── tracing-core v0.1.10 (*)
├── tracing-opentelemetry v0.5.0
│   ├── tracing v0.1.15 (*)
│   ├── tracing-core v0.1.10 (*)
│   ├── tracing-log v0.1.1 (*)
│   └── tracing-subscriber v0.2.6 (*)
└── tracing-subscriber v0.2.6 (*)

Platform

Linux luca 4.15.0-106-generic #107-Ubuntu SMP Thu Jun 4 11:27:52 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Crates

tracing-opentelemetry / tracing-error

Description

Logging a struct that holds a SpanTrace causes a core dump due to a deadlock on the RwLock held by the Registry:

thread 'main' panicked at 'rwlock read lock would result in deadlock', /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/macros.rs:13:23

You can check a minimum example here: https://github.com/LukeMathWalker/tracing-min
RUST_BACKTRACE=1 cargo run should reproduce the issue.

The relevant snippet is here:

#[derive(Debug)]
pub struct Dummy(SpanTrace);

#[tracing::instrument]
pub fn test() {
    let culprit = Dummy(SpanTrace::capture());
    tracing::warn!("It goes boom! - {:?}", culprit);
}

fn main() {
    init_telemetry();
    let tracer = global::tracer("test");
    tracer.in_span("span", move |_cx| {
        let _ = test();
    });
}

Looking at the backtrace

   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1069
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1504
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:198
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:218
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:511
  11: std::panicking::begin_panic
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/panicking.rs:438
  12: std::sys::unix::rwlock::RWLock::read
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/macros.rs:13
  13: std::sys_common::rwlock::RWLock::read
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/sys_common/rwlock.rs:26
  14: std::sync::rwlock::RwLock<T>::read
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/sync/rwlock.rs:185
  15: <tracing_subscriber::registry::sharded::Data as tracing_subscriber::registry::SpanData>::extensions
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-subscriber-0.2.6/src/registry/sharded.rs:349
  16: tracing_subscriber::registry::SpanRef<R>::extensions
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-subscriber-0.2.6/src/registry/mod.rs:279
  17: tracing_error::layer::ErrorLayer<S,F>::get_context
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-error-0.1.2/src/layer.rs:95
  18: tracing_error::layer::WithContext::with_context
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-error-0.1.2/src/layer.rs:114
  19: tracing_error::backtrace::SpanTrace::with_spans::{{closure}}
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-error-0.1.2/src/backtrace.rs:119
  20: tracing::span::Span::with_subscriber::{{closure}}
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-0.1.15/src/span.rs:883
  21: core::option::Option<T>::map
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/option.rs:456
  22: tracing::span::Span::with_subscriber
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-0.1.15/src/span.rs:881
  23: tracing_error::backtrace::SpanTrace::with_spans
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-error-0.1.2/src/backtrace.rs:117
  24: <tracing_error::backtrace::SpanTrace as core::fmt::Debug>::fmt
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-error-0.1.2/src/backtrace.rs:257
  25: <&T as core::fmt::Debug>::fmt
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/fmt/mod.rs:1973
  26: core::fmt::builders::DebugTuple::field::{{closure}}
             at src/libcore/fmt/builders.rs:347
  27: core::result::Result<T,E>::and_then
             at src/libcore/result.rs:729
  28: core::fmt::builders::DebugTuple::field
             at src/libcore/fmt/builders.rs:334
  29: <tracing_min::Dummy as core::fmt::Debug>::fmt
             at src/main.rs:42
  30: core::fmt::write
             at src/libcore/fmt/mod.rs:1069
  31: <core::fmt::Arguments as core::fmt::Display>::fmt
             at src/libcore/fmt/mod.rs:422
  32: <core::fmt::Arguments as core::fmt::Debug>::fmt
             at src/libcore/fmt/mod.rs:415
  33: <&T as core::fmt::Debug>::fmt
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/fmt/mod.rs:1973
  34: core::fmt::write
             at src/libcore/fmt/mod.rs:1069
  35: core::fmt::Write::write_fmt
             at /rustc/49cae55760da0a43428eba73abcb659bb70cf2e4/src/libcore/fmt/mod.rs:193
  36: alloc::fmt::format
             at src/liballoc/fmt.rs:586
  37: <tracing_opentelemetry::layer::SpanEventVisitor as tracing_core::field::Visit>::record_debug
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-opentelemetry-0.5.0/src/layer.rs:160
  38: <core::fmt::Arguments as tracing_core::field::Value>::record
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/field.rs:426
  39: <&T as tracing_core::field::Value>::record
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/field.rs:418
  40: tracing_core::field::ValueSet::record
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/field.rs:685
  41: tracing_core::event::Event::record
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/event.rs:89
  42: <tracing_opentelemetry::layer::OpenTelemetryLayer<S,T> as tracing_subscriber::layer::Layer<S>>::on_event
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-opentelemetry-0.5.0/src/layer.rs:521
  43: <tracing_subscriber::layer::Layered<L,S> as tracing_core::subscriber::Subscriber>::event
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-subscriber-0.2.6/src/layer.rs:599
  44: <tracing_subscriber::layer::Layered<L,S> as tracing_core::subscriber::Subscriber>::event
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-subscriber-0.2.6/src/layer.rs:598
  45: tracing_core::dispatcher::Dispatch::event
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/dispatcher.rs:471
  46: tracing_core::event::Event::dispatch::{{closure}}
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/event.rs:36
  47: tracing_core::dispatcher::get_default::{{closure}}
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/dispatcher.rs:330
  48: std::thread::local::LocalKey<T>::try_with
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  49: tracing_core::dispatcher::get_default
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/dispatcher.rs:317
  50: tracing_core::event::Event::dispatch
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/tracing-core-0.1.10/src/event.rs:35
  51: tracing_min::test
             at src/main.rs:48
  52: tracing_min::main::{{closure}}
             at src/main.rs:55
  53: opentelemetry::api::trace::tracer::Tracer::in_span
             at /home/luca/.cargo/registry/src/g.yxqyang.asia-1ecc6299db9ec823/opentelemetry-0.6.0/src/api/trace/tracer.rs:330
  54: tracing_min::main
             at src/main.rs:54
  55: std::rt::lang_start::{{closure}}
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/rt.rs:67
  56: std::rt::lang_start_internal::{{closure}}
             at src/libstd/rt.rs:52
  57: std::panicking::try::do_call
             at src/libstd/panicking.rs:331
  58: std::panicking::try
             at src/libstd/panicking.rs:274
  59: std::panic::catch_unwind
             at src/libstd/panic.rs:394
  60: std::rt::lang_start_internal
             at src/libstd/rt.rs:51
  61: std::rt::lang_start
             at /home/luca/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/rt.rs:67
  62: main
  63: __libc_start_main
  64: _start

I think the story goes more or less like this:

• the tracing::warn call triggers on_event on the OpenTelemetry layer

  tracing/tracing-opentelemetry/src/layer.rs

  Line 497 in 4fe9033

  fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {

• we start visiting things associated with the Event

  tracing/tracing-opentelemetry/src/layer.rs

  Line 521 in 4fe9033

  event.record(&mut SpanEventVisitor(&mut otel_event));

  
  while we hold a mutable reference to the extensions on the span

  tracing/tracing-opentelemetry/src/layer.rs

  Line 501 in 4fe9033

  if let Some(builder) = extensions.get_mut::<api::SpanBuilder>() {

  (the write end of the RwLock)
• the visitor calls debug on the logged struct which in turns calls debug on the SpanTrace, which triggers
  

  tracing/tracing-error/src/layer.rs

  Line 82 in 4fe9033

  fn get_context(

  
  where we try to get read-access to the RwLock held by the Registry, hence the deadlock (which is detected and converted to a panic).

[LukeMathWalker]

A potential solution is to decouple read operations that are taking place in on_event on the OpenTelemetry layer from write operations - first collect all the information you need with the visitor holding the read end of the lock, then drop it and get a write lock.
Going from

fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        // Ignore events that are not in the context of a span
        if let Some(span) = ctx.lookup_current() {
            let mut extensions = span.extensions_mut();
            if let Some(builder) = extensions.get_mut::<api::SpanBuilder>() {
                #[cfg(feature = "tracing-log")]
                let normalized_meta = event.normalized_metadata();
                #[cfg(feature = "tracing-log")]
                let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
                #[cfg(not(feature = "tracing-log"))]
                let meta = event.metadata();
                let mut otel_event = api::Event::new(
                    String::new(),
                    SystemTime::now(),
                    vec![
                        api::Key::new("level").string(meta.level().to_string()),
                        api::Key::new("target").string(meta.target()),
                    ],
                );

                if builder.status_code.is_none() && *meta.level() == tracing_core::Level::ERROR {
                    builder.status_code = Some(api::StatusCode::Unknown);
                }

                event.record(&mut SpanEventVisitor(&mut otel_event));

                if let Some(ref mut events) = builder.message_events {
                    events.push(otel_event);
                } else {
                    builder.message_events = Some(vec![otel_event]);
                }
            }
        };
    }

to

    fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) {
        // Ignore events that are not in the context of a span
        if let Some(span) = ctx.lookup_current() {
            #[cfg(feature = "tracing-log")]
            let normalized_meta = event.normalized_metadata();
            #[cfg(feature = "tracing-log")]
            let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
            #[cfg(not(feature = "tracing-log"))]
            let meta = event.metadata();
            let mut otel_event = api::Event::new(
                String::new(),
                SystemTime::now(),
                vec![
                    api::Key::new("level").string(meta.level().to_string()),
                    api::Key::new("target").string(meta.target()),
                ],
            );

            event.record(&mut SpanEventVisitor(&mut otel_event));
            let mut extensions = span.extensions_mut();
            if let Some(builder) = extensions.get_mut::<api::SpanBuilder>() {

                if builder.status_code.is_none() && *meta.level() == tracing_core::Level::ERROR {
                    builder.status_code = Some(api::StatusCode::Unknown);
                }

                if let Some(ref mut events) = builder.message_events {
                    events.push(otel_event);
                } else {
                    builder.message_events = Some(vec![otel_event]);
                }
            }
        };
    }

does indeed fix the issue.
Shall I open a PR with this fix?

On the other side, I can see this being quite a dangerous trap for other people writing their own layers and not expecting SpanTrace to cause such issues.

[hawkw]

Hmm, this is a pretty interesting case. I think the fix you're proposing would indeed work (and is probably worth moving forward with regardless), however, you're definitely right that it would be worthwhile to solve this problem in the general case so it doesn't happen with other layer implementations.

We could solve this problem by changing SpanTrace to format the span context when captured, rather than when formatted, but I don't think that would be ideal: lazily formatting SpanTraces is a big part of the performance picture for tracing-error, since it allows us to avoid any additional allocations when capturing and defer the expensive formatting so that it only happens if we actually want to format the SpanTrace.

This is also the kind of issue that get_default unsetting the current dispatcher was intended to prevent. Since the on_event call is inside of a get_default closure (in the event! macro), the nested get_default call from SpanTrace should fail...so I wonder what's stopping that from happening in this case.

[hawkw]

This is also the kind of issue that get_default unsetting the current dispatcher was intended to prevent. Since the on_event call is inside of a get_default closure (in the event! macro), the nested get_default call from SpanTrace should fail...so I wonder what's stopping that from happening in this case.

Oh, I see, SpanTrace uses the span's dispatcher reference:

tracing/tracing-error/src/backtrace.rs

Line 117 in 4fe9033

self.span.with_subscriber(|(id, s)| {

so it doesn't go through get_default.

This is actually correct --- the error might be formatted in the context of a different subscriber from the one that originally recorded the span, so we want to ensure we ask that subscriber for the data (as other subscribers wouldn't have it, and could have totally different span data for the same ID).

We could consider adding a check in SpanTrace to see if the default dispatcher is unset, and returning that the span trace is unavailable if so. However, that would mean that SpanTraces can never be formatted by a subscriber, which also seems not ideal. In a truly just world, I think we would only output "span trace unavailable" if it would actually cause a deadlock...

[jtescher]

On the otel side this change looks good to me, there should be no tracing spans that do not have a builder associated so the behavior should be identical when moving the event logic before the builder check. @LukeMathWalker happy to review a PR to that effect.

[LukeMathWalker]

PR is open @jtescher 👍 #765

[jtescher]

@hawkw should we keep this issue open for additional checks? or open a different issue as the main issue here was fixed in #765

[hawkw]

I gave this some thought, and I think we can ship a new design for extensions in tracing-subscriber 0.3 where locking is at the level of individual extensions. This will be a breaking change, so it will have to wait for 0.3, but it should fix this kind of issue across the board.

[NOBLES5E]

This bug is still present in the latest version (reproducible when enable color_eyre's tracing support, and tracing-opentelemetry).

[TmLev]

Also hitting this from time to time with color_eyre and tracing-opentelemetry, and it's pretty annoying. We have a critical infrastructure service which should not panic, but simply logging an error with SpanTrace crashes everything down.

[mkatychev]

I can confirm this happens with A the error-stack is enabled with the spantrace feature as well:
error-stack = { version = "0.3.0", features = ["std", "spantrace"] }