Log lines name their trace under a scoped subscriber too (#408)
WithTrace found a line's span with Span::current(), which asks the thread's default dispatcher; inside an event under a scoped subscriber (with_default), tracing's re-entrancy guard answers with none, so every line went out without trace_id and span_id. Production, on the global dispatcher, was not affected, but the log test had to go global for it. The JSON layer now carries a small layer of its own that keeps the subscriber it is registered with (on_register_dispatch, a weak handle), and the formatter takes the registry's current span from its own context and asks tracing-opentelemetry for its context through that handle (get_otel_context), with no dispatcher lookup. The log test runs scoped again; with the old formatter it fails for want of the ids. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01RqkrVDqdiQEMWAkNGQ2tYA
This commit is contained in:
@@ -104,6 +104,8 @@ where
|
|||||||
S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
|
S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
|
||||||
W: for<'w> tracing_subscriber::fmt::MakeWriter<'w> + Send + Sync + 'static,
|
W: for<'w> tracing_subscriber::fmt::MakeWriter<'w> + Send + Sync + 'static,
|
||||||
{
|
{
|
||||||
|
use tracing_subscriber::Layer as _;
|
||||||
|
let registered = Registered::default();
|
||||||
tracing_subscriber::fmt::layer()
|
tracing_subscriber::fmt::layer()
|
||||||
.fmt_fields(tracing_subscriber::fmt::format::JsonFields::new())
|
.fmt_fields(tracing_subscriber::fmt::format::JsonFields::new())
|
||||||
.event_format(WithTrace(
|
.event_format(WithTrace(
|
||||||
@@ -112,11 +114,26 @@ where
|
|||||||
.flatten_event(true)
|
.flatten_event(true)
|
||||||
.with_current_span(current_span)
|
.with_current_span(current_span)
|
||||||
.with_span_list(false),
|
.with_span_list(false),
|
||||||
|
registered.clone(),
|
||||||
))
|
))
|
||||||
.with_writer(writer)
|
.with_writer(writer)
|
||||||
|
.and_then(registered)
|
||||||
}
|
}
|
||||||
|
|
||||||
pub struct WithTrace<F>(pub F);
|
/// The subscriber the log layer is part of, as it was handed over on registration. The span's
|
||||||
|
/// OpenTelemetry context is reached through it: `Span::current()` asks the thread's default
|
||||||
|
/// dispatcher, which inside an event under a scoped subscriber (`with_default`) is hidden by
|
||||||
|
/// tracing's re-entrancy guard, and every line went out without its ids (#408).
|
||||||
|
#[derive(Clone, Default)]
|
||||||
|
struct Registered(std::sync::Arc<std::sync::OnceLock<tracing::dispatcher::WeakDispatch>>);
|
||||||
|
|
||||||
|
impl<S: tracing::Subscriber> tracing_subscriber::Layer<S> for Registered {
|
||||||
|
fn on_register_dispatch(&self, subscriber: &tracing::Dispatch) {
|
||||||
|
let _ = self.0.set(subscriber.downgrade());
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
|
struct WithTrace<F>(F, Registered);
|
||||||
|
|
||||||
impl<S, N, F> tracing_subscriber::fmt::FormatEvent<S, N> for WithTrace<F>
|
impl<S, N, F> tracing_subscriber::fmt::FormatEvent<S, N> for WithTrace<F>
|
||||||
where
|
where
|
||||||
@@ -131,9 +148,14 @@ where
|
|||||||
ev: &tracing::Event<'_>,
|
ev: &tracing::Event<'_>,
|
||||||
) -> std::fmt::Result {
|
) -> std::fmt::Result {
|
||||||
use opentelemetry::trace::TraceContextExt;
|
use opentelemetry::trace::TraceContextExt;
|
||||||
use tracing_opentelemetry::OpenTelemetrySpanExt;
|
let dispatch = self.1.0.get().and_then(tracing::dispatcher::WeakDispatch::upgrade);
|
||||||
let current = tracing::Span::current();
|
// The registry's own current span, not the one this layer's filter would show.
|
||||||
let sc = if current.is_none() { None } else { Some(current.context().span().span_context().clone()) };
|
let sc = ctx
|
||||||
|
.current_span()
|
||||||
|
.id()
|
||||||
|
.zip(dispatch)
|
||||||
|
.and_then(|(id, d)| tracing_opentelemetry::get_otel_context(id, &d))
|
||||||
|
.map(|cx| cx.span().span_context().clone());
|
||||||
let Some(sc) = sc.filter(|c| c.is_valid()) else {
|
let Some(sc) = sc.filter(|c| c.is_valid()) else {
|
||||||
return self.0.format_event(ctx, w, ev);
|
return self.0.format_event(ctx, w, ev);
|
||||||
};
|
};
|
||||||
|
|||||||
@@ -69,11 +69,8 @@ mod tests {
|
|||||||
let sub = tracing_subscriber::registry()
|
let sub = tracing_subscriber::registry()
|
||||||
.with(json_layer(move || Lines(b.clone()), true))
|
.with(json_layer(move || Lines(b.clone()), true))
|
||||||
.with(tracing_opentelemetry::layer().with_tracer(provider.tracer("test")));
|
.with(tracing_opentelemetry::layer().with_tracer(provider.tracer("test")));
|
||||||
// Global, as production's is: under a scoped one (with_default), Span::current() inside the
|
// Scoped, where the formatter once found no dispatcher and no line named its trace (#408).
|
||||||
// formatter finds no dispatcher, so no line would name its trace. Other tests' events
|
tracing::subscriber::with_default(sub, || {
|
||||||
// land here too, hence feed names only this test uses.
|
|
||||||
tracing::subscriber::set_global_default(sub).unwrap();
|
|
||||||
{
|
|
||||||
let out = Emitter::terminal();
|
let out = Emitter::terminal();
|
||||||
out.emit(Event::FeedDone { feed: "log-test-f".into(), new: 2, downloaded: 1, failed: 0, torrents: 0 });
|
out.emit(Event::FeedDone { feed: "log-test-f".into(), new: 2, downloaded: 1, failed: 0, torrents: 0 });
|
||||||
let scan = tracing::info_span!("scan");
|
let scan = tracing::info_span!("scan");
|
||||||
@@ -86,7 +83,7 @@ mod tests {
|
|||||||
bytes: 1234,
|
bytes: 1234,
|
||||||
});
|
});
|
||||||
out.emit(Event::FeedError { feed: "log-test-g".into(), msg: "HTTP 404 Not Found".into() });
|
out.emit(Event::FeedError { feed: "log-test-g".into(), msg: "HTTP 404 Not Found".into() });
|
||||||
}
|
});
|
||||||
let text = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
|
let text = String::from_utf8(buf.lock().unwrap().clone()).unwrap();
|
||||||
let lines: Vec<serde_json::Value> = text.lines().map(|l| serde_json::from_str(l).expect(l)).collect();
|
let lines: Vec<serde_json::Value> = text.lines().map(|l| serde_json::from_str(l).expect(l)).collect();
|
||||||
let find = |ev: &str| {
|
let find = |ev: &str| {
|
||||||
|
|||||||
Reference in New Issue
Block a user