search

tokio-rs / tracing

Application level tracing for Rust.
https://tracing.rs
MIT License
5.19k stars 677 forks source link

Tried to drop a ref to Id(3), but no such span exists! #2870

Open scw00 opened 5 months ago

scw00 commented 5 months ago

Bug Report

tried to drop a ref to Id(3), but no such span exists!

Version

tracing-core-0.1.32 tracing-subscriber-0.3.18

Platform

linux

Crates

tracing-subscriber or tracing-core

Description

I created a span S from a dispatcher A. And the Span::inner has recorded the dispatcher A. Then I spawn a future with_dispatch(B). The dispatcher B replace the global dispatcher A with Kind::Scope.

After that, The spawned future is correctly entered the span S, but panicked on dropping because the tracing-subscriber can't find the span's id from local (Kind::Scope) dispatcher B , Which is existed in dispatchter A.

rklaehn commented 1 week ago

I am seeing this as well. I got a pretty complex program ( https://github.com/n0-computer/iroh ) where I am hunting for an unexpected panic, and I am seeing multiple things like this in the logs:

thread 'test_sync_via_relay' panicked at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/sharded.rs:350:21:
tried to drop a ref to Id(11260098580054061), but no such span exists!

If the ids are assigned consecutively, this seems like a very high number, indicating some kind of memory corruption. If they are assigned randomly, this would be not out of the usual...

rklaehn commented 1 week ago

Here is a full stack trace, in case it helps:

This is on an m1 mac, by the way.

thread 'test_sync_via_relay' panicked at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/sharded.rs:350:21:
tried to drop a ref to Id(4), but no such span exists!
stack backtrace:
   0: rust_begin_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:652:5
   1: core::panicking::panic_fmt
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:72:14
   2: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::try_close
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/sharded.rs:350:21
   3: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::try_close
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:186:12
   4: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::try_close
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:186:12
   5: tracing_core::dispatcher::Dispatch::try_close
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-core-0.1.32/src/dispatcher.rs:705:9
   6: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::exit::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/sharded.rs:303:52
   7: tracing_core::dispatcher::get_default
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-core-0.1.32/src/dispatcher.rs:391:16
   8: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::exit
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/sharded.rs:303:17
   9: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::exit
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:162:9
  10: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::exit
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:162:9
  11: tracing_core::dispatcher::Dispatch::exit
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-core-0.1.32/src/dispatcher.rs:638:9
  12: tracing::span::Span::do_exit
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:1054:13
  13: <tracing::span::Entered as core::ops::drop::Drop>::drop
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:1568:9
  14: core::ptr::drop_in_place<tracing::span::Entered>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  15: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop::__drop_inner
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/pin-project-lite-0.2.14/src/lib.rs:1337:17
  16: tracing::instrument::_::<impl core::ops::drop::Drop for tracing::instrument::Instrumented<T>>::drop
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/pin-project-lite-0.2.14/src/lib.rs:1345:17
  17: core::ptr::drop_in_place<tracing::instrument::Instrumented<iroh_net::relay::http::server::ServerState::serve::{{closure}}::{{closure}}>>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  18: core::ptr::drop_in_place<alloc::boxed::Box<tracing::instrument::Instrumented<iroh_net::relay::http::server::ServerState::serve::{{closure}}::{{closure}}>>>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  19: core::ptr::drop_in_place<core::pin::Pin<alloc::boxed::Box<tracing::instrument::Instrumented<iroh_net::relay::http::server::ServerState::serve::{{closure}}::{{closure}}>>>>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  20: core::ptr::drop_in_place<tokio::runtime::task::core::Stage<core::pin::Pin<alloc::boxed::Box<tracing::instrument::Instrumented<iroh_net::relay::http::server::ServerState::serve::{{closure}}::{{closure}}>>>>>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  21: tokio::runtime::task::core::Core<T,S>::set_stage::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/core.rs:382:41
  22: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/loom/std/unsafe_cell.rs:16:9
  23: tokio::runtime::task::core::Core<T,S>::set_stage
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/core.rs:382:9
  24: tokio::runtime::task::core::Core<T,S>::drop_future_or_output
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/core.rs:347:13
  25: tokio::runtime::task::harness::cancel_task::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/harness.rs:453:9
  26: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  27: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panic/unwind_safe.rs:272:9
  28: std::panicking::try::do_call
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:559:40
  29: ___rust_try
  30: std::panicking::try
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:523:19
  31: std::panic::catch_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panic.rs:149:14
  32: tokio::runtime::task::harness::cancel_task
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/harness.rs:452:15
  33: tokio::runtime::task::harness::Harness<T,S>::shutdown
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/harness.rs:247:9
  34: tokio::runtime::task::raw::shutdown
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/raw.rs:311:5
  35: tokio::runtime::task::raw::RawTask::shutdown
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/raw.rs:235:18
  36: tokio::runtime::task::Task<S>::shutdown
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/mod.rs:418:9
  37: tokio::runtime::task::list::OwnedTasks<S>::close_and_shutdown_all
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/task/list.rs:156:25
  38: tokio::runtime::scheduler::current_thread::shutdown2
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/scheduler/current_thread/mod.rs:251:5
  39: tokio::runtime::scheduler::current_thread::CurrentThread::shutdown::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/scheduler/current_thread/mod.rs:231:28
  40: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/scheduler/current_thread/mod.rs:737:68
  41: tokio::runtime::context::scoped::Scoped<T>::set
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/context/scoped.rs:40:9
  42: tokio::runtime::context::set_scheduler::{{closure}}
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/context.rs:180:26
  43: std::thread::local::LocalKey<T>::try_with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:286:12
  44: std::thread::local::LocalKey<T>::with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:262:9
  45: tokio::runtime::context::set_scheduler
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/context.rs:180:9
  46: tokio::runtime::scheduler::current_thread::CoreGuard::enter
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/scheduler/current_thread/mod.rs:737:27
  47: tokio::runtime::scheduler::current_thread::CurrentThread::shutdown
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/scheduler/current_thread/mod.rs:230:13
  48: <tokio::runtime::runtime::Runtime as core::ops::drop::Drop>::drop
             at /Users/rklaehn/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.0/src/runtime/runtime.rs:474:17
  49: core::ptr::drop_in_place<tokio::runtime::runtime::Runtime>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ptr/mod.rs:514:1
  50: sync::test_sync_via_relay
             at ./tests/sync.rs:573:10
  51: sync::test_sync_via_relay::{{closure}}
             at ./tests/sync.rs:488:35
  52: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
  53: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
mladedav commented 1 week ago

@rklaehn unless you're using multiple different subscribers/dispatchers, your problem will be different to the original one.

Can you open a new issue please so we can keep it separate?