diff --git a/Cargo.lock b/Cargo.lock index b362be90..051e1414 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3494,6 +3494,7 @@ dependencies = [ "opentelemetry_sdk", "tokio", "tracing", + "tracing-opentelemetry", "tracing-subscriber", ] @@ -4907,7 +4908,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "32497e9a4c7b38532efcdebeef879707aa9f794296a4f0244f6f69e9bc8574bd" dependencies = [ "fastrand", - "getrandom 0.3.4", + "getrandom 0.4.3", "once_cell", "rustix 1.1.4", "windows-sys 0.61.2", @@ -5260,6 +5261,21 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "db97caf9d906fbde555dd62fa95ddba9eecfd14cb388e4f491a66d74cd5fb79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-opentelemetry" +version = "0.33.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "adbc64cba7137545b8044cb1fe9814f7aacf3c6b5f9b45be8bb5db538befdb26" +dependencies = [ + "js-sys", + "opentelemetry", + "tracing", + "tracing-core", + "tracing-subscriber", + "web-time", ] [[package]] @@ -5416,6 +5432,12 @@ dependencies = [ "vsimd", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "version_check" version = "0.9.5" diff --git a/THIRD-PARTY-LICENSES.md b/THIRD-PARTY-LICENSES.md index 6d1996f7..62e67b30 100644 --- a/THIRD-PARTY-LICENSES.md +++ b/THIRD-PARTY-LICENSES.md @@ -20,7 +20,7 @@ dependencies (tests, benchmarks) are excluded because they are not shipped. | License | Crates | | --- | --- | | `Apache-2.0` | 336 | -| `MIT` | 71 | +| `MIT` | 72 | | `Unicode-3.0` | 19 | | `BSD-3-Clause` | 8 | | `ISC` | 4 | @@ -8506,6 +8506,7 @@ Used by: - `tracing-attributes` 0.1.31 — - `tracing-core` 0.1.36 — +- `tracing-opentelemetry` 0.33.0 — - `tracing-subscriber` 0.3.23 — - `tracing` 0.1.44 — diff --git a/crates/ourios-telemetry/Cargo.toml b/crates/ourios-telemetry/Cargo.toml index 5bd463ce..9ebb10e7 100644 --- a/crates/ourios-telemetry/Cargo.toml +++ b/crates/ourios-telemetry/Cargo.toml @@ -16,21 +16,26 @@ path = "src/lib.rs" # The OTel metrics API. Library crates depend only on this (via # `global::meter`); this crate is the one place the heavy SDK + # exporter live (RFC 0001 §6.8 "Export architecture"). -opentelemetry = { version = "0.32", default-features = false, features = ["metrics"] } -# The SDK: MeterProvider + periodic reader (metrics) and LoggerProvider + +opentelemetry = { version = "0.32", default-features = false, features = ["metrics", "trace"] } +# The SDK: MeterProvider + periodic reader (metrics), LoggerProvider + # batch processor (logs — the CLAUDE.md §6.3 dogfooding path: Ourios's -# own logs ship as the OTel Logs signal). `rt-tokio` drives the periodic -# export on the tokio runtime the server already runs. -opentelemetry_sdk = { version = "0.32", default-features = false, features = ["metrics", "logs", "rt-tokio"] } -# The OTLP push exporter over gRPC (tonic), both signals. This is the +# own logs ship as the OTel Logs signal), and TracerProvider + batch span +# processor (traces — RFC 0038, request-scoped self-tracing). `rt-tokio` +# drives the periodic/batch export on the tokio runtime the server runs. +opentelemetry_sdk = { version = "0.32", default-features = false, features = ["metrics", "logs", "trace", "rt-tokio"] } +# The OTLP push exporter over gRPC (tonic), all three signals. This is the # export path pinned by the §6.8 amendment — push over OTLP, not a # scrape endpoint (and for logs, not plain stderr). -opentelemetry-otlp = { version = "0.32", default-features = false, features = ["metrics", "logs", "grpc-tonic"] } +opentelemetry-otlp = { version = "0.32", default-features = false, features = ["metrics", "logs", "trace", "grpc-tonic"] } # The OTel-recommended Rust logging bridge: `tracing` events become OTel # log records through this appender (Rust has no end-user OTel logging # API; `tracing` is the front-end). opentelemetry-appender-tracing = { version = "0.32", default-features = false } -# The subscriber stack the bridge plugs into: `registry` composes layers, +# The OTel-recommended Rust *tracing* bridge (RFC 0038): `tracing` spans +# become OTel spans through this layer, and the appender above then stamps +# the active span's trace/span ids onto every log record it emits. +tracing-opentelemetry = { version = "0.33", default-features = false } +# The subscriber stack the bridges plug into: `registry` composes layers, # `env-filter` gives RUST_LOG-style filtering (and the loop guard muting # the exporter's own tonic/hyper internals), `fmt` is the human-readable # stderr copy. @@ -43,9 +48,9 @@ tracing-subscriber = { version = "0.3", default-features = false, features = ["r testing = ["opentelemetry_sdk/testing"] [dev-dependencies] -opentelemetry_sdk = { version = "=0.32.1", default-features = false, features = ["metrics", "testing"] } +opentelemetry_sdk = { version = "=0.32.1", default-features = false, features = ["metrics", "logs", "trace", "testing"] } tokio = { version = "=1.53.0", default-features = false, features = ["rt", "rt-multi-thread", "macros"] } -# Emit `tracing` events in the bridge test. +# Emit `tracing` events + spans in the bridge / correlation tests. tracing = { version = "=0.1.44", default-features = false, features = ["std"] } [lints] diff --git a/crates/ourios-telemetry/src/lib.rs b/crates/ourios-telemetry/src/lib.rs index d58dcd80..0b95bf9c 100644 --- a/crates/ourios-telemetry/src/lib.rs +++ b/crates/ourios-telemetry/src/lib.rs @@ -33,15 +33,22 @@ use std::time::Duration; use opentelemetry::global; +use opentelemetry::trace::TracerProvider as _; use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge; -use opentelemetry_otlp::{LogExporter, MetricExporter, WithExportConfig}; +use opentelemetry_otlp::{LogExporter, MetricExporter, SpanExporter, WithExportConfig}; use opentelemetry_sdk::Resource; use opentelemetry_sdk::logs::SdkLoggerProvider; use opentelemetry_sdk::metrics::{PeriodicReader, SdkMeterProvider}; +use opentelemetry_sdk::trace::{Sampler, SdkTracerProvider}; use tracing_subscriber::layer::SubscriberExt as _; use tracing_subscriber::util::SubscriberInitExt as _; use tracing_subscriber::{EnvFilter, Layer as _}; +/// The instrumentation-scope name for the tracer that opens Ourios's own +/// spans (RFC 0038). The library crates create instruments through +/// `global::meter("ourios.")`; spans go through this one tracer. +const TRACER_SCOPE: &str = "ourios"; + /// Default OTLP export interval. The OpenTelemetry spec's default /// periodic-reader interval is 60 s; we follow it unless a deployment /// overrides. @@ -61,17 +68,30 @@ pub struct TelemetryConfig { pub otlp_endpoint: Option, /// Periodic-reader export interval ([`DEFAULT_EXPORT_INTERVAL`]). pub export_interval: Duration, + /// Dogfood the traces signal (RFC 0038). `true` installs a + /// `TracerProvider` + `tracing-opentelemetry` layer, so `tracing` + /// spans become `OTel` spans and every log record carries the active + /// span's `trace_id`/`span_id`. `false` restores the logs+metrics-only + /// posture (no tracer, no `trace_id` on logs). + pub traces_enabled: bool, + /// Trace sampler (RFC 0038 §3.4). `None` → `parentbased_always_on` + /// (the `OTel` default; the disciplined span count sits far below the + /// ~1000 traces/sec threshold `OTel` says to sample at). `Some(r)` → + /// `parentbased_traceidratio` at ratio `r` in `[0.0, 1.0]`. + pub trace_sample_ratio: Option, } impl TelemetryConfig { /// Config for `service_name` with spec defaults (default endpoint, - /// [`DEFAULT_EXPORT_INTERVAL`]). + /// [`DEFAULT_EXPORT_INTERVAL`], traces on, always-on sampler). #[must_use] pub fn new(service_name: impl Into) -> Self { Self { service_name: service_name.into(), otlp_endpoint: None, export_interval: DEFAULT_EXPORT_INTERVAL, + traces_enabled: true, + trace_sample_ratio: None, } } } @@ -123,6 +143,9 @@ pub struct TelemetryGuard { provider: SdkMeterProvider, /// `None` on the metrics-only paths ([`init_in_memory`], tests). logger: Option, + /// `None` when traces are disabled (`traces_enabled: false`) or on the + /// metrics-only paths. + tracer: Option, } impl TelemetryGuard { @@ -139,7 +162,11 @@ impl TelemetryGuard { Some(logger) => logger.shutdown().map_err(TelemetryError::Shutdown), None => Ok(()), }; - metrics.and(logs) + let traces = match &self.tracer { + Some(tracer) => tracer.shutdown().map_err(TelemetryError::Shutdown), + None => Ok(()), + }; + metrics.and(logs).and(traces) } /// Export pending metrics now, without tearing the pipeline down — @@ -164,6 +191,9 @@ impl Drop for TelemetryGuard { if let Some(logger) = &self.logger { let _ = logger.shutdown(); } + if let Some(tracer) = &self.tracer { + let _ = tracer.shutdown(); + } } } @@ -173,6 +203,37 @@ fn resource(service_name: &str) -> Resource { .build() } +/// A boxed subscriber layer over the root `Registry`, so a conditionally-built +/// layer (the traces layer, absent when traces are disabled) can be stored in a +/// binding before entering the subscriber chain. +type BoxedLayer = Box + Send + Sync>; + +/// A `RUST_LOG`-honouring filter with the telemetry-induced-telemetry loop +/// guard applied (`CLAUDE.md` §6.3): the OTLP exporters are themselves +/// tonic/hyper clients, so their own `tracing` events **and spans** must be +/// muted, or every export would generate more telemetry to export. The `off` +/// directives win over `RUST_LOG`. Shared by the logs appender bridge and the +/// traces layer. Directives are compile-time constants; an unparsable one is +/// skipped rather than panicking. +fn guarded_env_filter() -> EnvFilter { + let mut filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")); + for directive in [ + "hyper=off", + "tonic=off", + "h2=off", + "tower=off", + "reqwest=off", + "opentelemetry=off", + "opentelemetry_sdk=off", + "opentelemetry_otlp=off", + ] { + if let Ok(directive) = directive.parse() { + filter = filter.add_directive(directive); + } + } + filter +} + /// Build the OTLP push `MeterProvider` **and** the OTLP `LoggerProvider` /// with its `tracing` bridge, install them process-globally, and return /// the [`TelemetryGuard`] that owns them. @@ -223,37 +284,62 @@ pub fn init(config: &TelemetryConfig) -> Result let log_exporter = builder.build()?; let logger = SdkLoggerProvider::builder() .with_batch_exporter(log_exporter) - .with_resource(resource) + .with_resource(resource.clone()) .build(); - global::set_meter_provider(provider.clone()); + // Traces (RFC 0038): a `TracerProvider` over the OTLP batch span + // exporter, whose tracer feeds a `tracing-opentelemetry` layer — so + // `tracing` spans become OTel spans and their ids reach every log + // record through the appender bridge. Also built before installing any + // global (the span exporter is the last fallible step). `None` when + // traces are disabled, which keeps today's logs+metrics posture exactly. + // The sampler is `parentbased_always_on` by default, or + // `parentbased_traceidratio` when a ratio is configured (RFC 0038 §3.4). + let (tracer, otel_layer): (Option, Option) = + if config.traces_enabled { + let mut builder = SpanExporter::builder().with_tonic(); + if let Some(endpoint) = &config.otlp_endpoint { + builder = builder.with_endpoint(endpoint.clone()); + } + let span_exporter = builder.build()?; + let sampler = match config.trace_sample_ratio { + // Clamp defensively to the documented `[0.0, 1.0]`. The + // RFC 0038 §3.4 config-file layer rejects an out-of-range + // ratio at startup before it reaches here; this only guards a + // direct library caller from a surprising sampler. + Some(ratio) => Sampler::ParentBased(Box::new(Sampler::TraceIdRatioBased( + ratio.clamp(0.0, 1.0), + ))), + None => Sampler::ParentBased(Box::new(Sampler::AlwaysOn)), + }; + let tracer_provider = SdkTracerProvider::builder() + .with_batch_exporter(span_exporter) + .with_sampler(sampler) + .with_resource(resource) + .build(); + let layer = tracing_opentelemetry::layer() + .with_tracer(tracer_provider.tracer(TRACER_SCOPE)) + .with_filter(guarded_env_filter()) + .boxed(); + (Some(tracer_provider), Some(layer)) + } else { + (None, None) + }; - // The bridge honours `RUST_LOG` (default `info`) like the stderr copy, - // so exported volume can be turned down (`warn`) or up (`debug`) the - // same way. On top of that sits the telemetry-induced-telemetry loop - // guard (OTel self-observability guidelines): the OTLP exporter is - // itself a tonic/hyper client, so its internal `tracing` events must - // not re-enter the bridge or every failed export would emit records - // that trigger more exports — the guard's `off` directives always win, - // whatever `RUST_LOG` says. The directives are compile-time constants; - // an unparsable one is skipped rather than panicking. - let mut bridge_filter = - EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info")); - for directive in [ - "hyper=off", - "tonic=off", - "h2=off", - "tower=off", - "reqwest=off", - "opentelemetry=off", - "opentelemetry_sdk=off", - "opentelemetry_otlp=off", - ] { - if let Ok(directive) = directive.parse() { - bridge_filter = bridge_filter.add_directive(directive); - } - } - let bridge = OpenTelemetryTracingBridge::new(&logger).with_filter(bridge_filter); + global::set_meter_provider(provider.clone()); + // The global tracer provider is set *after* `try_init` confirms the traces + // layer is wired (below) — not here. Setting it before would, on a lost + // subscriber-install race, leave the global pointing at a provider this + // function then shuts down (the metrics global is safe to set early: it is + // kept regardless of the subscriber outcome). + + // The appender bridge and the traces layer both honour `RUST_LOG` + // (default `info`) with the telemetry-induced-telemetry loop guard + // applied (`guarded_env_filter`): the OTLP exporters are tonic/hyper + // clients, so their internal events *and spans* must not re-enter the + // pipeline or every failed export would emit more telemetry to export — + // the guard's `off` directives always win over `RUST_LOG`. + let bridge = OpenTelemetryTracingBridge::new(&logger).with_filter(guarded_env_filter()); // Human-readable copy on stderr — stdout is reserved for the // binary's machine-parsed start-up lines (bound-port announcements). // `RUST_LOG` overrides the default `info`. @@ -263,22 +349,36 @@ pub fn init(config: &TelemetryConfig) -> Result // `try_init` (not `init`): a process can only ever have one global // subscriber. If one is already installed (a test harness), keep it — // metrics still work and the caller's logs still go wherever that - // subscriber sends them. In that case the bridge was not wired, so - // tear the logger pipeline down rather than keep an idle batch - // processor alive for the process lifetime. - let logger = if tracing_subscriber::registry() + // subscriber sends them. In that case the bridge/traces layer were not + // wired, so tear the logger and tracer pipelines down rather than keep + // idle batch processors alive for the process lifetime. + let installed = tracing_subscriber::registry() + .with(otel_layer) .with(bridge) .with(fmt) .try_init() - .is_ok() - { - Some(logger) + .is_ok(); + let (logger, tracer) = if installed { + // The subscriber — and its traces layer — is live, so register the + // tracer provider globally now (any direct `global::tracer(...)` use + // resolves against a running pipeline). + if let Some(tracer_provider) = &tracer { + global::set_tracer_provider(tracer_provider.clone()); + } + (Some(logger), tracer) } else { let _ = logger.shutdown(); - None + if let Some(tracer_provider) = &tracer { + let _ = tracer_provider.shutdown(); + } + (None, None) }; - Ok(TelemetryGuard { provider, logger }) + Ok(TelemetryGuard { + provider, + logger, + tracer, + }) } /// Build an in-memory metrics pipeline for tests: a `MeterProvider` @@ -318,6 +418,7 @@ pub fn init_in_memory( TelemetryGuard { provider, logger: None, + tracer: None, }, exporter, ) @@ -346,6 +447,7 @@ mod tests { let guard = TelemetryGuard { provider, logger: None, + tracer: None, }; // Act. @@ -402,4 +504,51 @@ mod tests { "the tracing event should surface as an OTel log record, got {records:?}", ); } + + // Scenario RFC0038.1 (unit slice): with the traces layer and the appender + // bridge on the same subscriber, a `tracing::info!` emitted *inside* a + // `tracing` span carries that span's (non-zero) `trace_id`/`span_id` on the + // resulting OTel log record — the correlation the reported gap was about. + #[tokio::test(flavor = "multi_thread", worker_threads = 1)] + async fn rfc0038_1_log_within_a_span_carries_trace_context() { + use opentelemetry::trace::{SpanId, TraceId}; + use opentelemetry_sdk::logs::InMemoryLogExporter; + use opentelemetry_sdk::trace::InMemorySpanExporter; + + // Arrange — a tracer + logger over in-memory exporters, wired through + // the same two bridges `init` installs. + let span_exporter = InMemorySpanExporter::default(); + let tracer_provider = SdkTracerProvider::builder() + .with_simple_exporter(span_exporter) + .with_resource(resource("ourios-test")) + .build(); + let log_exporter = InMemoryLogExporter::default(); + let logger = SdkLoggerProvider::builder() + .with_simple_exporter(log_exporter.clone()) + .with_resource(resource("ourios-test")) + .build(); + let subscriber = tracing_subscriber::registry() + .with(tracing_opentelemetry::layer().with_tracer(tracer_provider.tracer(TRACER_SCOPE))) + .with(OpenTelemetryTracingBridge::new(&logger)); + + // Act — emit a log *inside* an entered span. + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("ourios.test.request"); + let _enter = span.enter(); + tracing::info!("a log emitted within the span"); + }); + logger.force_flush().expect("logs flush"); + + // Assert — the log carries a non-zero trace context. + let records = log_exporter.get_emitted_logs().expect("logs exported"); + let correlated = records.iter().any(|log| { + log.record + .trace_context() + .is_some_and(|tc| tc.trace_id != TraceId::INVALID && tc.span_id != SpanId::INVALID) + }); + assert!( + correlated, + "a log emitted inside a span should carry a non-zero trace_id/span_id, got {records:?}", + ); + } }