If an argument of a span!() call has a Debug implementation which in turn calls any tracing call (e.g. event!() or another span!()), tracing-tree panics. This happens in rustc, where in some cases the Debug implementation may have something to log, e.g. here->here->here.
Here is a minimum reproducible example, I'm using "tracing 0.1.44", "tracing-subscriber 0.3.22", "tracing-tree 0.4.1":
use std::fmt::{self, Debug, Formatter};
use tracing_subscriber::filter::{EnvFilter};
use tracing_subscriber::layer::{Layer, SubscriberExt};
use tracing_tree::HierarchicalLayer;
struct Baz {}
impl Debug for Baz {
fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result {
tracing::info!("Baz");
f.debug_struct("Baz").finish()
}
}
fn main() {
let subscriber = tracing_subscriber::Registry::default()
.with(HierarchicalLayer::default())
.with(HierarchicalLayer::default().with_filter(EnvFilter::default()));
tracing::subscriber::set_global_default(subscriber).unwrap();
let obj = Baz {};
let _s = tracing::info_span!("main", ?obj).entered();
}When run, the program outputs main obj=Baz and then crashes. The crash seems to happen here, "in new_span but span does not exist": https://github.com/davidbarsky/tracing-tree/blob/main/src/lib.rs#L451
Here is the full backtrace
thread 'main' panicked at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-tree-0.4.1/src/lib.rs:451:33:
in new_span but span does not exist
stack backtrace:
0: 0x55cd9d2f45d2 - std::backtrace_rs::backtrace::libunwind::trace::h2d45396358f41939
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
1: 0x55cd9d2f45d2 - std::backtrace_rs::backtrace::trace_unsynchronized::hffcefc0b67f1d6e2
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
2: 0x55cd9d2f45d2 - std::sys::backtrace::_print_fmt::hd72f71d23b436b92
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/sys/backtrace.rs:66:9
3: 0x55cd9d2f45d2 - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::hdcfcb6d4c8489523
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/sys/backtrace.rs:39:26
4: 0x55cd9d314e93 - core::fmt::rt::Argument::fmt::h2c56b3114963061a
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/fmt/rt.rs:173:76
5: 0x55cd9d314e93 - core::fmt::write::h8a494366950f23bb
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/fmt/mod.rs:1468:25
6: 0x55cd9d2f2153 - std::io::default_write_fmt::ha27fbccbc65eb6fa
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/io/mod.rs:639:11
7: 0x55cd9d2f2153 - std::io::Write::write_fmt::h6556609fca33d0b1
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/io/mod.rs:1954:13
8: 0x55cd9d2f4422 - std::sys::backtrace::BacktraceLock::print::hb2a626a81e06b2dc
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/sys/backtrace.rs:42:9
9: 0x55cd9d2f54c3 - std::panicking::default_hook::{{closure}}::h4f78485264f12d10
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:300:27
10: 0x55cd9d2f52a5 - std::panicking::default_hook::h2c66fc99e962531d
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:327:9
11: 0x55cd9d2f5e95 - std::panicking::rust_panic_with_hook::h33ac55f64bbd807d
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:833:13
12: 0x55cd9d2f5c2a - std::panicking::begin_panic_handler::{{closure}}::h30e7cb89678a57fe
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:706:13
13: 0x55cd9d2f4ad9 - std::sys::backtrace::__rust_end_short_backtrace::hed60f27456c16ced
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/sys/backtrace.rs:174:18
14: 0x55cd9d2f58bd - __rustc[de2ca18b4c54d5b8]::rust_begin_unwind
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:697:5
15: 0x55cd9d312ea0 - core::panicking::panic_fmt::h62f63d096dd276af
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/panicking.rs:75:14
16: 0x55cd9d312e7b - core::panicking::panic_display::h784ac6e2afc29348
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/panicking.rs:268:5
17: 0x55cd9d312e7b - core::option::expect_failed::h091923fb77e757a1
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/option.rs:2139:5
18: 0x55cd9d2477b9 - core::option::Option<T>::expect::h968ca79a9e2a7077
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/option.rs:964:21
19: 0x55cd9d23ed80 - <tracing_tree::HierarchicalLayer<W,FT> as tracing_subscriber::layer::Layer<S>>::on_new_span::h30cbc804b11155c0
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-tree-0.4.1/src/lib.rs:451:33
20: 0x55cd9d24839a - <tracing_subscriber::filter::layer_filters::Filtered<L,F,S> as tracing_subscriber::layer::Layer<S>>::on_new_span::{{closure}}::h24eac559e981011c
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/filter/layer_filters/mod.rs:797:24
21: 0x55cd9d24961e - tracing_subscriber::filter::layer_filters::FilterState::did_enable::hea7b34f99e3a83ee
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/filter/layer_filters/mod.rs:1182:13
22: 0x55cd9d249cc8 - tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable::{{closure}}::hfc7b424bb96be0b1
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/filter/layer_filters/mod.rs:642:46
23: 0x55cd9d23dd3c - std::thread::local::LocalKey<T>::try_with::h8be03692708e23d6
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:315:12
24: 0x55cd9d23d9ce - std::thread::local::LocalKey<T>::with::h0c2098087f1fc898
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:279:20
25: 0x55cd9d249ab4 - tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable::h4a1704ea8881d75c
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/filter/layer_filters/mod.rs:642:19
26: 0x55cd9d248294 - <tracing_subscriber::filter::layer_filters::Filtered<L,F,S> as tracing_subscriber::layer::Layer<S>>::on_new_span::hf386a22aa402b5db
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/filter/layer_filters/mod.rs:794:14
27: 0x55cd9d239fca - <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::new_span::hfa8989f25ab0b390
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.22/src/layer/layered.rs:132:20
28: 0x55cd9d2b96e9 - tracing_core::dispatcher::Dispatch::new_span::ha358db97f96d79fc
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.36/src/dispatcher.rs:556:27
29: 0x55cd9d2b9e82 - tracing::span::Span::make_with::h2763a074ddee4d21
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.44/src/span.rs:570:27
30: 0x55cd9d2b9e2a - tracing::span::Span::new_with::h2918edc731545635
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.44/src/span.rs:449:9
31: 0x55cd9d2b9dcd - tracing::span::Span::new::{{closure}}::h385b77dc54d4bf06
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.44/src/span.rs:438:44
32: 0x55cd9d2b918f - tracing_core::dispatcher::get_default::hefca37874147e2d7
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.36/src/dispatcher.rs:386:16
33: 0x55cd9d2b9d95 - tracing::span::Span::new::h1760769531bdfc47
at ~/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.44/src/span.rs:438:9
34: 0x55cd9d24c2c0 - nested::main::hd231becd0798c743
at ./src/bin/nested.rs:22:14
35: 0x55cd9d24579b - core::ops::function::FnOnce::call_once::h29a67ba2ff45752a
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:253:5
36: 0x55cd9d24d66e - std::sys::backtrace::__rust_begin_short_backtrace::h5751217f7821e998
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/backtrace.rs:158:18
37: 0x55cd9d24a091 - std::rt::lang_start::{{closure}}::h2f32a6747d8e8123
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:206:18
38: 0x55cd9d2ef0d0 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h638295a043b40957
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/core/src/ops/function.rs:290:21
39: 0x55cd9d2ef0d0 - std::panicking::catch_unwind::do_call::hbd68098bdea1ca50
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:589:40
40: 0x55cd9d2ef0d0 - std::panicking::catch_unwind::h50591d85bf847c7c
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:552:19
41: 0x55cd9d2ef0d0 - std::panic::catch_unwind::h2487b4c4f2ae22c6
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panic.rs:359:14
42: 0x55cd9d2ef0d0 - std::rt::lang_start_internal::{{closure}}::h61f0945cc6c9a811
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/rt.rs:175:24
43: 0x55cd9d2ef0d0 - std::panicking::catch_unwind::do_call::h34b9c3722acd6bd1
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:589:40
44: 0x55cd9d2ef0d0 - std::panicking::catch_unwind::hf9a822ea043fb0d6
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panicking.rs:552:19
45: 0x55cd9d2ef0d0 - std::panic::catch_unwind::h5b3cac802237ed89
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/panic.rs:359:14
46: 0x55cd9d2ef0d0 - std::rt::lang_start_internal::h34f9328d113fd60a
at /rustc/1159e78c4747b02ef996e55082b704c09b970588/library/std/src/rt.rs:171:5
47: 0x55cd9d24a077 - std::rt::lang_start::h336dcf9d50485b1f
at ~/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:205:5
48: 0x55cd9d24c42e - main
49: 0x7f4603593635 - <unknown>
50: 0x7f46035936e9 - __libc_start_main
51: 0x55cd9d238e85 - _start
52: 0x0 - <unknown>
If an argument of a
span!()call has aDebugimplementation which in turn calls any tracing call (e.g.event!()or anotherspan!()), tracing-tree panics. This happens inrustc, where in some cases theDebugimplementation may have something to log, e.g. here->here->here.Here is a minimum reproducible example, I'm using "tracing 0.1.44", "tracing-subscriber 0.3.22", "tracing-tree 0.4.1":
When run, the program outputs
main obj=Bazand then crashes. The crash seems to happen here, "in new_span but span does not exist": https://github.com/davidbarsky/tracing-tree/blob/main/src/lib.rs#L451Here is the full backtrace