diff --git a/.changeset/tracing-span-bridge.md b/.changeset/tracing-span-bridge.md new file mode 100644 index 0000000..45fabc8 --- /dev/null +++ b/.changeset/tracing-span-bridge.md @@ -0,0 +1,8 @@ +--- +'@smooai/observability': minor +--- + +Rust: new `tracing-bridge` feature and `OtelSdkHandle::tracing_span_layer()`, so +`tracing` SPANS (`#[instrument]`, `info_span!`) actually export. The SDK set the +global tracer provider but never bridged `tracing` spans into it, so they were +printed and dropped while the service looked fully instrumented. diff --git a/rust/Cargo.lock b/rust/Cargo.lock index b00616a..bf9deea 100644 --- a/rust/Cargo.lock +++ b/rust/Cargo.lock @@ -1872,6 +1872,7 @@ dependencies = [ "tower-layer", "tower-service", "tracing", + "tracing-opentelemetry", "tracing-subscriber", "uuid", "wiremock", @@ -2178,6 +2179,22 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-opentelemetry" +version = "0.33.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "adbc64cba7137545b8044cb1fe9814f7aacf3c6b5f9b45be8bb5db538befdb26" +dependencies = [ + "js-sys", + "opentelemetry", + "smallvec", + "tracing", + "tracing-core", + "tracing-log", + "tracing-subscriber", + "web-time", +] + [[package]] name = "tracing-subscriber" version = "0.3.23" diff --git a/rust/observability/Cargo.toml b/rust/observability/Cargo.toml index 8ea5984..ed1eb82 100644 --- a/rust/observability/Cargo.toml +++ b/rust/observability/Cargo.toml @@ -93,11 +93,23 @@ reqwest-middleware = { version = "0.5", optional = true } # spans (tower/gen_ai/reqwest, all OTel-native) is correlated automatically. The # host installs the layer via `OtelSdkHandle::tracing_appender_layer()`. opentelemetry-appender-tracing = "0.32" +# Feature `tracing-bridge`: the SPAN half of the tracing↔OTel story. The appender +# above turns tracing EVENTS into OTLP logs; this turns tracing SPANS into OTLP +# spans. Without it, `#[instrument]` / `info_span!` spans never export even +# though the global tracer provider is installed (th-eaccd1). +tracing-opentelemetry = { version = "0.33", optional = true } +tracing-subscriber = { version = "0.3", features = ["registry", "std"], optional = true } +tracing = { version = "0.1", optional = true } [features] default = [] # OTel server-span layer for Tower/Axum services. tower = ["dep:tower-layer", "dep:tower-service", "dep:pin-project-lite"] +# Install a `tracing` -> OTel bridge so `#[instrument]` / `info_span!` spans +# actually export. Without it, bootstrap() sets the global tracer provider but +# `tracing` spans go to whatever subscriber the host installed — usually one +# with no OTel layer, so they are printed and never exported (th-eaccd1). +tracing-bridge = ["dep:tracing-opentelemetry", "dep:tracing-subscriber", "dep:tracing"] # OTel client-span middleware for reqwest. Pulls reqwest as a DIRECT dep (the # only thing in this crate that needs it directly — the OTLP transport is on # smooai-fetch as of SMOODEV-2029). diff --git a/rust/observability/src/otel.rs b/rust/observability/src/otel.rs index b1e7790..84d5119 100644 --- a/rust/observability/src/otel.rs +++ b/rust/observability/src/otel.rs @@ -145,6 +145,45 @@ impl OtelSdkHandle { .as_ref() .map(OpenTelemetryTracingBridge::new) } + + /// The tracing→OTel-**span** bridge layer, or `None` when traces are + /// disabled (no traces endpoint configured). Requires feature + /// `tracing-bridge`. + /// + /// [`Self::tracing_appender_layer`] handles tracing EVENTS (→ OTLP logs). + /// This handles tracing SPANS (→ OTLP spans), and without it they do not + /// export at all — which is subtler than it sounds, because + /// `bootstrap()` sets the global tracer provider either way. Code that opens + /// spans through the OpenTelemetry API exports fine; code that uses + /// `#[instrument]` or `info_span!` — most Rust code, and most libraries — + /// silently does not. + /// + /// That gap cost a production LLM-tracing outage (th-eaccd1): the per-turn + /// `gen_ai.chat` span, carrying model and token usage, was a `tracing` span + /// in a subscriber with no bridge. It was printed to stdout for months while + /// every dashboard reported the service as instrumented. + /// + /// ```ignore + /// use tracing_subscriber::prelude::*; + /// let obs = smooai_observability::bootstrap().await; + /// let mut reg = tracing_subscriber::registry().with(EnvFilter::from_default_env()); + /// if let Some(spans) = obs.otel.as_ref().and_then(|h| h.tracing_span_layer()) { + /// reg.with(spans).init(); // tracing spans now EXPORT + /// } + /// ``` + /// + /// Bound to this handle's provider rather than the global one, so it exports + /// through the same pipeline this SDK flushes and shuts down. + #[cfg(feature = "tracing-bridge")] + pub fn tracing_span_layer(&self) -> Option> + where + S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>, + { + use opentelemetry::trace::TracerProvider as _; + self.tracer_provider.as_ref().map(|tp| { + tracing_opentelemetry::layer().with_tracer(tp.tracer("smooai-observability/tracing")) + }) + } } static INSTALLED: OnceCell = OnceCell::new(); diff --git a/rust/observability/tests/tracing_span_bridge.rs b/rust/observability/tests/tracing_span_bridge.rs new file mode 100644 index 0000000..3b8e4fd --- /dev/null +++ b/rust/observability/tests/tracing_span_bridge.rs @@ -0,0 +1,137 @@ +#![cfg(feature = "tracing-bridge")] +//! `tracing` spans must actually reach the exporter — the gap that made a +//! production LLM-tracing outage invisible (th-eaccd1). +//! +//! `bootstrap()` sets the global tracer provider, so anything opened through the +//! OpenTelemetry API exports. `tracing` spans (`#[instrument]`, `info_span!`) +//! do NOT: they need a `tracing-opentelemetry` layer inside the installed +//! subscriber. Without one they are printed and dropped, while every other +//! signal reports the service as instrumented. +//! +//! These assert on spans that arrive at a collector, not on the layer being +//! constructible — a layer that builds and exports nothing is precisely the bug. + +use std::sync::{Arc, Mutex}; + +use opentelemetry_sdk::trace::{SdkTracerProvider, SpanData, SpanExporter}; + +/// Collects exported spans so the test can assert on what actually left. +#[derive(Clone, Default, Debug)] +struct CollectingExporter { + spans: Arc>>, +} + +impl SpanExporter for CollectingExporter { + fn export( + &self, + batch: Vec, + ) -> impl std::future::Future + Send { + self.spans.lock().unwrap().extend(batch); + async { Ok(()) } + } +} + +fn provider_with(exporter: CollectingExporter) -> SdkTracerProvider { + SdkTracerProvider::builder() + .with_simple_exporter(exporter) + .build() +} + +/// The headline case: a `tracing` span, opened the way application code opens +/// them, must arrive at the exporter with its name intact. +/// +/// Remove the layer from the registry and this fails with zero spans — which is +/// exactly what production looked like. +#[test] +fn a_tracing_span_reaches_the_exporter() { + use opentelemetry::trace::TracerProvider as _; + use tracing_subscriber::prelude::*; + + let exporter = CollectingExporter::default(); + let provider = provider_with(exporter.clone()); + let layer = tracing_opentelemetry::layer() + .with_tracer(provider.tracer("smooai-observability/tracing")); + + let subscriber = tracing_subscriber::registry().with(layer); + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("gen_ai.chat", gen_ai.request.model = "test-model"); + let _entered = span.enter(); + }); + + provider.force_flush().ok(); + let spans = exporter.spans.lock().unwrap(); + assert!( + spans.iter().any(|s| s.name == "gen_ai.chat"), + "a tracing span did not reach the exporter — exported names: {:?}", + spans.iter().map(|s| s.name.as_ref()).collect::>() + ); +} + +/// The negative control, and the reason the first test means anything: the SAME +/// span with NO bridge layer must export NOTHING. +/// +/// This is the production configuration that looked healthy — provider +/// installed, spans opened, nothing exported. +#[test] +fn without_the_bridge_layer_a_tracing_span_exports_nothing() { + let exporter = CollectingExporter::default(); + let provider = provider_with(exporter.clone()); + + // A subscriber with NO otel layer — what a host gets from a plain + // fmt-only `init_telemetry()`. + let subscriber = tracing_subscriber::registry(); + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("gen_ai.chat"); + let _entered = span.enter(); + }); + + provider.force_flush().ok(); + assert!( + exporter.spans.lock().unwrap().is_empty(), + "spans exported without a bridge layer — then the bridge is not what makes them export, \ + and the first test proves nothing" + ); +} + +/// Span ATTRIBUTES must survive the bridge. A span that exports its name but +/// drops `gen_ai.request.model` / token usage is useless for LLM tracing — the +/// attributes are the product. +#[test] +fn span_attributes_survive_the_bridge() { + use opentelemetry::trace::TracerProvider as _; + use tracing_subscriber::prelude::*; + + let exporter = CollectingExporter::default(); + let provider = provider_with(exporter.clone()); + let layer = tracing_opentelemetry::layer() + .with_tracer(provider.tracer("smooai-observability/tracing")); + + tracing::subscriber::with_default(tracing_subscriber::registry().with(layer), || { + let span = tracing::info_span!( + "gen_ai.chat", + gen_ai.request.model = "groq-gpt-oss-120b", + gen_ai.usage.input_tokens = 42_i64 + ); + let _entered = span.enter(); + }); + + provider.force_flush().ok(); + let spans = exporter.spans.lock().unwrap(); + let chat = spans + .iter() + .find(|s| s.name == "gen_ai.chat") + .expect("gen_ai.chat span exported"); + let keys: Vec = chat + .attributes + .iter() + .map(|kv| kv.key.as_str().to_string()) + .collect(); + assert!( + keys.iter().any(|k| k == "gen_ai.request.model"), + "model attribute lost crossing the bridge; got {keys:?}" + ); + assert!( + keys.iter().any(|k| k == "gen_ai.usage.input_tokens"), + "token usage lost crossing the bridge; got {keys:?}" + ); +}