From f5a3847a2164640d24bdd6a391ba5c75ef259d78 Mon Sep 17 00:00:00 2001 From: rays Date: Sat, 7 Nov 2026 13:41:04 +0000 Subject: [PATCH] Production's log lines name their trace again (#411, #408) ba18b44 had the JSON layer find a line's span context through the dispatch it was registered with, and production's logging wrapped that layer in an Option, whose Layer impl does not pass on_register_dispatch on: the layer never got its dispatch and every line went out without trace_id and span_id. The log test built a subscriber of its own, without the Option, and passed. Both services now box their stderr layer instead of an Option of each kind (a Box passes registration on), the formatter falls back to the default dispatcher when it was never registered, which a global subscriber's lines find, and the log test builds the subscriber with the function init uses, writing to its buffer, so a wrapper like this one is under test. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RqkrVDqdiQEMWAkNGQ2tYA --- crates/directory/src/main.rs | 13 ++++++--- crates/directory/src/otel.rs | 8 ++++-- crates/ipx/src/logging.rs | 53 ++++++++++++++++++++++-------------- 3 files changed, 46 insertions(+), 28 deletions(-) diff --git a/crates/directory/src/main.rs b/crates/directory/src/main.rs index 3f2a545..be2c9f5 100644 --- a/crates/directory/src/main.rs +++ b/crates/directory/src/main.rs @@ -83,11 +83,16 @@ async fn serve(path: &Path) -> Result<()> { let filter = || EnvFilter::try_from_env("DIRECTORY_LOG").unwrap_or_else(|_| "ipx_directory=info".into()); // Traces to Tempo when OTEL_EXPORTER_OTLP_ENDPOINT is set, joining ipx's (#213). let otel = ipx_directory::otel::provider("ipx-directory")?; + // Each line's own fields say all its span did, and the span said it again (#363); the trace + // and span ids lead to the trace instead, as ipx's do (#375). Boxed rather than an Option of + // each: Option's Layer does not pass on_register_dispatch on, which the JSON layer needs (#408). + let stderr: Box + Send + Sync> = if json { + ipx_directory::otel::json_layer(std::io::stderr, false).with_filter(filter()).boxed() + } else { + tracing_subscriber::fmt::layer().with_writer(std::io::stderr).with_filter(filter()).boxed() + }; tracing_subscriber::registry() - .with((!json).then(|| tracing_subscriber::fmt::layer().with_writer(std::io::stderr).with_filter(filter()))) - // Each line's own fields say all its span did, and the span said it again (#363); the trace - // and span ids lead to the trace instead, as ipx's do (#375). - .with(json.then(|| ipx_directory::otel::json_layer(std::io::stderr, false).with_filter(filter()))) + .with(stderr) .with(otel.as_ref().map(|p| { use opentelemetry::trace::TracerProvider; tracing_opentelemetry::layer() diff --git a/crates/directory/src/otel.rs b/crates/directory/src/otel.rs index 6d9e821..3857505 100644 --- a/crates/directory/src/otel.rs +++ b/crates/directory/src/otel.rs @@ -148,13 +148,15 @@ where ev: &tracing::Event<'_>, ) -> std::fmt::Result { use opentelemetry::trace::TraceContextExt; - let dispatch = self.1.0.get().and_then(tracing::dispatcher::WeakDispatch::upgrade); + // Without one (a wrapper that does not pass registration on, as Option does not), the + // default dispatcher, which a global subscriber's lines still find. + let registered = self.1.0.get().and_then(tracing::dispatcher::WeakDispatch::upgrade); + let dispatch = registered.unwrap_or_else(|| tracing::dispatcher::get_default(Clone::clone)); // The registry's own current span, not the one this layer's filter would show. let sc = ctx .current_span() .id() - .zip(dispatch) - .and_then(|(id, d)| tracing_opentelemetry::get_otel_context(id, &d)) + .and_then(|id| tracing_opentelemetry::get_otel_context(id, &dispatch)) .map(|cx| cx.span().span_context().clone()); let Some(sc) = sc.filter(|c| c.is_valid()) else { return self.0.format_event(ctx, w, ev); diff --git a/crates/ipx/src/logging.rs b/crates/ipx/src/logging.rs index 75de95c..bb61912 100644 --- a/crates/ipx/src/logging.rs +++ b/crates/ipx/src/logging.rs @@ -8,36 +8,51 @@ use tracing_subscriber::EnvFilter; /// Sets up logging: to stderr, as text or as JSON (`IPX_LOG_FORMAT`), into the ring the page's log /// reads, and to the trace exporter when there is one. pub(crate) fn init(otel: Option<&opentelemetry_sdk::trace::SdkTracerProvider>) { + use tracing_subscriber::util::SubscriberInitExt; + let json = std::env::var("IPX_LOG_FORMAT").is_ok_and(|f| f.eq_ignore_ascii_case("json")); + subscriber(json, otel, std::io::stderr).init(); +} + +/// The subscriber `init` installs, writing to `out`: the test's lines are production's. +fn subscriber( + json: bool, + otel: Option<&opentelemetry_sdk::trace::SdkTracerProvider>, + out: W, +) -> impl tracing::Subscriber + Send + Sync +where + W: for<'w> tracing_subscriber::fmt::MakeWriter<'w> + Send + Sync + 'static, +{ // Everything goes to stderr as before, and is mirrored into a ring the UI can read. use tracing_subscriber::Layer; use tracing_subscriber::layer::SubscriberExt; - use tracing_subscriber::util::SubscriberInitExt; // Two filters, deliberately different. stderr follows IPX_LOG; the in-app buffer // keeps debug as well, so the log view can show protocol traffic and routine // skips that would be noise on a terminal. IPX_UI_LOG overrides it. let stderr_filter = || EnvFilter::try_from_env("IPX_LOG").unwrap_or_else(|_| "ipx=info".into()); // One JSON object a line for Loki (#91), with each event's fields as its own; text // otherwise, for someone reading a terminal. - let json = std::env::var("IPX_LOG_FORMAT").is_ok_and(|f| f.eq_ignore_ascii_case("json")); let ui_filter = EnvFilter::try_from_env("IPX_UI_LOG").unwrap_or_else(|_| "ipx=debug".into()); - tracing_subscriber::registry() - .with((!json).then(|| { - tracing_subscriber::fmt::layer() - .with_writer(std::io::stderr) - // Colour for a terminal only: in docker logs and Loki the escapes are noise - // every query has to strip (#88). - .with_ansi(IsTerminal::is_terminal(&std::io::stderr())) - .with_filter(stderr_filter()) - })) - .with(json.then(|| json_layer(std::io::stderr, true).with_filter(stderr_filter()))) - .with(logbuf::RingLayer.with_filter(ui_filter)) - .with(otel.as_ref().map(|p| { + // Boxed rather than an Option of each: Option's Layer does not pass on_register_dispatch on, + // which the JSON layer finds each line's trace by (#408). + let stderr: Box + Send + Sync> = if json { + json_layer(out, true).with_filter(stderr_filter()).boxed() + } else { + tracing_subscriber::fmt::layer() + .with_writer(out) + // Colour for a terminal only: in docker logs and Loki the escapes are noise + // every query has to strip (#88). + .with_ansi(IsTerminal::is_terminal(&std::io::stderr())) + .with_filter(stderr_filter()) + .boxed() + }; + tracing_subscriber::registry().with(stderr).with(logbuf::RingLayer.with_filter(ui_filter)).with(otel.as_ref().map( + |p| { use opentelemetry::trace::TracerProvider; tracing_opentelemetry::layer() .with_tracer(p.tracer("ipx")) .with_filter(EnvFilter::new("ipx=info,ipx_feed=info")) - })) - .init(); + }, + )) } #[cfg(test)] @@ -61,14 +76,10 @@ mod tests { #[test] fn a_scans_events_are_json_lines_with_the_fields_grafana_reads() { - use opentelemetry::trace::TracerProvider; - use tracing_subscriber::layer::SubscriberExt; let buf = Arc::new(Mutex::new(vec![])); let b = buf.clone(); let provider = opentelemetry_sdk::trace::SdkTracerProvider::builder().build(); - let sub = tracing_subscriber::registry() - .with(json_layer(move || Lines(b.clone()), true)) - .with(tracing_opentelemetry::layer().with_tracer(provider.tracer("test"))); + let sub = subscriber(true, Some(&provider), move || Lines(b.clone())); // Scoped, where the formatter once found no dispatcher and no line named its trace (#408). tracing::subscriber::with_default(sub, || { let out = Emitter::terminal();