Description
Bug Report
Version
tracing v0.1.29
tracing-core v0.1.21
Crates
tracing-core
Description
tracing_core::Dispatch holds an Arc<dyn Subscriber + Send + Sync>. Because of the trait bounds involved here, the Arc is not UnwindSafe or RefUnwindSafe as this requires its contained type to be RefUnwindSafe.
This is an annoying limitation as it means I cannot pass a Dispatch across a catch_unwind boundary. Or, in my case, I can't hold it in an adaptor to another logging system that requires RefUnwindSafe.
What's more, I believe that Dispatch actually explicitly should require its Subscriber to be RefUnwindSafe. The reason being, the fact that Dispatchs are stuffed into thread-local and global storage means they already cross catch_unwind boundaries. This means if I write a Subscriber that is not RefUnwindSafe, and I panic in a way that breaks its invariants but catch that with catch_unwind, the Subscriber will still be active on the outside despite the invariants broken.
To demonstrate this, I wrote a sample Subscriber implementation that is Send and Sync, but is not RefUnwindSafe. It maintains a (rather trivial) invariant, that is temporarily broken during event() while a lock is held, and restored at the end. But it rather carelessly has a panic in the middle if the event doesn't have the message field. And the result of this is logging a message-free event during a catch_unwind breaks the subscriber permanently. I've included it below.
Also worth noting is that because Subscriber has to be Sync, it already has to handle the case of being accessed from multiple threads. This strongly suggests that it should be RefUnwindSafe as well, because you can spawn a thread and panic in that thread and then observe the broken invariant from your original thread without ever calling catch_unwind.
On a related note, Span also ends up being !RefUnwindSafe, but it has the additional problem where being RefUnwindSafe would require Metadata to also be RefUnwindSafe, which it currently isn't due to FieldSet, which in turn is due to callsite::Identifier. I don't believe callsite::Identifier ever actually invokes anything on its embedded dyn Callsite, so it should be able to simply declare itself to be UnwindSafe/RefUnwindSafe.
I also checked the latest tracing.rs docs and the problem still exists there, where Dispatch has a dyn Collect + Send + Sync with no mention of RefUnwindSafe.
Example code (Playground)
use parking_lot::Mutex;
use std::fmt::Debug;
use std::panic;
use tracing::{info, field, span, Event, Metadata, Subscriber};
struct BadSubscriber {
// this simulates a logical invariant. It should only be `true` while a
// method is executing, and should revert back to `false` after.
invariant: Mutex<bool>,
}
impl BadSubscriber {
fn new() -> Self {
Self {
invariant: Mutex::new(false),
}
}
}
impl Subscriber for BadSubscriber {
fn enabled(&self, _: &Metadata<'_>) -> bool {
true
}
// ignore spans
fn enter(&self, _: &span::Id) {}
fn exit(&self, _: &span::Id) {}
fn new_span(&self, _: &span::Attributes<'_>) -> span::Id {
span::Id::from_u64(0)
}
fn record(&self, _: &span::Id, _: &span::Record<'_>) {}
fn record_follows_from(&self, _: &span::Id, _: &span::Id) {}
fn event(&self, event: &Event<'_>) {
let mut guard = self.invariant.lock();
if *guard { panic!("invariant broken"); }
*guard = true;
// find the message field
let mut message = None;
event.record(&mut |field: &field::Field, value: &dyn Debug| {
if field.name() == "message" {
message = Some(format!("{:?}", value));
}
});
// oops we did something stupid here, this will panic if there's no message
println!("event: {}", message.unwrap());
// restore the invariant
*guard = false;
}
}
fn main() {
let _guard = tracing::dispatcher::set_default(&BadSubscriber::new().into());
info!("first message");
let _ = panic::catch_unwind(|| {
info!(foo = 42); // this panics, but is caught
});
info!("try again"); // this panics with "invariant broken"
// we never get to this point
}Output:
❯ cargo run
Finished dev [unoptimized + debuginfo] target(s) in 0.02s
Running `target/debug/asdf`
event: first message
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/main.rs:46:39
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'invariant broken', src/main.rs:36:21