diff --git a/rust/logger/Cargo.lock b/rust/logger/Cargo.lock index f759d64b..f42a5e3f 100644 --- a/rust/logger/Cargo.lock +++ b/rust/logger/Cargo.lock @@ -39,7 +39,7 @@ checksum = "c7c24de15d275a1ecfd47a380fb4d5ec9bfe0933f309ed5e705b775596a3574d" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -173,7 +173,7 @@ dependencies = [ "proc-macro2", "quote", "strsim", - "syn", + "syn 2.0.106", ] [[package]] @@ -184,7 +184,7 @@ checksum = "ac3984ec7bd6cfa798e62b4a642426a5be0e68f9401cfc2a01e3fa9ea2fcdb8d" dependencies = [ "darling_core", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -205,7 +205,7 @@ checksum = "97369cbbc041bc366949bc74d34658d6cda5621039731c6310521892a3a20ae0" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -307,7 +307,7 @@ checksum = "e835b70203e41293343137df5c0664546da5745f82ec9b84d40be8336958447b" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -770,6 +770,36 @@ version = "1.21.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "42f5e15c9953c5e4ccceeb2e7382a716482c34515315f7b03532b8b4e8393d2d" +[[package]] +name = "opentelemetry" +version = "0.32.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b0142c63252a9e054e68a4c61a5778f7b14f576274d593f8ce883d191a099682" +dependencies = [ + "futures-core", + "futures-sink", + "js-sys", + "pin-project-lite", + "thiserror", + "tracing", +] + +[[package]] +name = "opentelemetry_sdk" +version = "0.32.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9b59f80e1ac4d5ff7a2db8fb6c80badb7f0f3f858211fba08dd9aaec750894f9" +dependencies = [ + "futures-channel", + "futures-executor", + "futures-util", + "opentelemetry", + "percent-encoding", + "portable-atomic", + "rand", + "thiserror", +] + [[package]] name = "parking_lot" version = "0.12.4" @@ -816,7 +846,7 @@ checksum = "a990e22f43e84855daf260dded30524ef4a9021cc7541c26540500a50b624389" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -825,6 +855,12 @@ version = "0.2.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a89322df9ebe1c1578d689c92318e070967d1042b512afbe49518723f4e6d5cd" +[[package]] +name = "portable-atomic" +version = "1.14.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3d20d5497ef88037a52ff98267d066e7f11fcc5e99bbfbd58a42336193aacec3" + [[package]] name = "potential_utf" version = "0.1.3" @@ -840,6 +876,15 @@ version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391" +[[package]] +name = "ppv-lite86" +version = "0.2.21" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "85eae3c4ed2f50dcfe72643da4befc30deadb458a9b590d720cde2f2b1e97da9" +dependencies = [ + "zerocopy", +] + [[package]] name = "proc-macro2" version = "1.0.101" @@ -875,6 +920,35 @@ version = "5.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "69cdb34c158ceb288df11e18b4bd39de994f6657d83847bdffdbd7f346754b0f" +[[package]] +name = "rand" +version = "0.9.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b9ef1d0d795eb7d84685bca4f72f3649f064e6641543d3a8c415898726a57b41" +dependencies = [ + "rand_chacha", + "rand_core", +] + +[[package]] +name = "rand_chacha" +version = "0.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d3022b5f1df60f26e1ffddd6c66e8aa15de382ae63b3a0c1bfc0e4d3e3f325cb" +dependencies = [ + "ppv-lite86", + "rand_core", +] + +[[package]] +name = "rand_core" +version = "0.9.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "76afc826de14238e6e8c374ddcc1fa19e374fd8dd986b0d2af0d02377261d83c" +dependencies = [ + "getrandom", +] + [[package]] name = "redox_syscall" version = "0.5.17" @@ -901,7 +975,7 @@ checksum = "b7186006dcb21920990093f30e3dea63b7d6e977bf1256be20c3563a5db070da" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1003,7 +1077,7 @@ checksum = "8db53ae22f34573731bafa1db20f04027b2d25e02d8205921b569171699cdb33" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1060,7 +1134,7 @@ dependencies = [ "darling", "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1099,10 +1173,14 @@ dependencies = [ "colored", "lambda_runtime", "once_cell", + "opentelemetry", + "opentelemetry_sdk", "parking_lot", "serde", "serde_json", "tempfile", + "tracing", + "tracing-subscriber", "url", "uuid", ] @@ -1140,6 +1218,17 @@ dependencies = [ "unicode-ident", ] +[[package]] +name = "syn" +version = "3.0.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a207d6d6a2b7fc470b80443726053f18a2481b7e1eee970597051596567987a3" +dependencies = [ + "proc-macro2", + "quote", + "unicode-ident", +] + [[package]] name = "synstructure" version = "0.13.2" @@ -1148,7 +1237,7 @@ checksum = "728a70f3dbaf5bab7f0c4b1ac8d7ae5ea60a4b5549c8a5914361c99147a709d2" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1164,6 +1253,26 @@ dependencies = [ "windows-sys 0.61.0", ] +[[package]] +name = "thiserror" +version = "2.0.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09a43598840e33d5b0331f38c5e30d13bb11c11210a4b58f0d9b18a5a5eefcd9" +dependencies = [ + "thiserror-impl", +] + +[[package]] +name = "thiserror-impl" +version = "2.0.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "43cbfe0cf76104d42a574802844187e84a305e531ed54455f11fbde0f10541cd" +dependencies = [ + "proc-macro2", + "quote", + "syn 3.0.2", +] + [[package]] name = "thread_local" version = "1.1.9" @@ -1252,7 +1361,7 @@ checksum = "5c55a2eff8b69ce66c84f85e1da1c233edc36ceb85a2058d11b0d6a3c7e7569c" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1313,7 +1422,7 @@ checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1457,7 +1566,7 @@ dependencies = [ "log", "proc-macro2", "quote", - "syn", + "syn 2.0.106", "wasm-bindgen-shared", ] @@ -1479,7 +1588,7 @@ checksum = "9f07d2f20d4da7b26400c9f4a0511e6e0345b040694e8a75bd41d578fa4421d7" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", "wasm-bindgen-backend", "wasm-bindgen-shared", ] @@ -1514,7 +1623,7 @@ checksum = "a47fddd13af08290e67f4acabf4b459f647552718f683a7b415d290ac744a836" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1525,7 +1634,7 @@ checksum = "bd9211b69f8dcdfa817bfd14bf1c97c9188afa36f4750130fcdf3f400eca9fa8" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] [[package]] @@ -1666,10 +1775,30 @@ checksum = "38da3c9736e16c5d3c8c597a9aaa5d1fa565d0532ae05e27c24aa62fb32c0ab6" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", "synstructure", ] +[[package]] +name = "zerocopy" +version = "0.8.55" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b5a105cd7b140f6eeec8acff2ea38135d3cab283ada58540f629fe51e46696eb" +dependencies = [ + "zerocopy-derive", +] + +[[package]] +name = "zerocopy-derive" +version = "0.8.55" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0fe976fb70c78cd64cccfe3a6fc142244e8a77b70959b30faf9d0ac37ee228eb" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.106", +] + [[package]] name = "zerofrom" version = "0.1.6" @@ -1687,7 +1816,7 @@ checksum = "d71e5d6e06ab090c67b5e44993ec16b72dcbaabc526db883a360057678b48502" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", "synstructure", ] @@ -1721,5 +1850,5 @@ checksum = "5b96237efa0c878c64bd89c436f661be4e46b2f3eff1ebb976f7ef2321d2f58f" dependencies = [ "proc-macro2", "quote", - "syn", + "syn 2.0.106", ] diff --git a/rust/logger/Cargo.toml b/rust/logger/Cargo.toml index 3c1a93bc..e2fada6a 100644 --- a/rust/logger/Cargo.toml +++ b/rust/logger/Cargo.toml @@ -28,11 +28,21 @@ uuid = { version = "1", features = ["v4"] } chrono = { version = "0.4", features = ["serde", "clock"] } colored = "2" url = "2" +# OpenTelemetry **API only** (no SDK, no `@smooai/observability` — that would be +# circular): read the active span's trace_id/span_id for log↔trace correlation, +# and the `tracing` facade to tee lines into the observability OTLP appender. +tracing = { version = "0.1", default-features = false, features = ["std"] } lambda_runtime = { version = "0.13", optional = true } aws_lambda_events = { version = "0.16", default-features = false, features = [ "apigw", "sqs", ], optional = true } +opentelemetry = { version = "0.32.0", default-features = false, features = ["trace"] } [dev-dependencies] tempfile = "3" +# Correlation + tee tests: a real SDK tracer to mint an active span, and a +# tracing subscriber to capture the teed events (dev-only — the SDK dep is not +# circular; the crate itself depends on the OTel API only). +opentelemetry_sdk = { version = "0.32", features = ["trace"] } +tracing-subscriber = { version = "0.3", default-features = false, features = ["registry", "std"] } diff --git a/rust/logger/src/context.rs b/rust/logger/src/context.rs index e4ab7a3e..2c92ed00 100644 --- a/rust/logger/src/context.rs +++ b/rust/logger/src/context.rs @@ -17,6 +17,7 @@ pub enum ContextKey { CorrelationId, RequestId, TraceId, + SpanId, Namespace, Service, Duration, @@ -38,6 +39,7 @@ impl ContextKey { ContextKey::CorrelationId => "correlationId", ContextKey::RequestId => "requestId", ContextKey::TraceId => "traceId", + ContextKey::SpanId => "spanId", ContextKey::Namespace => "namespace", ContextKey::Service => "service", ContextKey::Duration => "duration", @@ -217,10 +219,34 @@ fn default_context_map() -> ContextMap { let id = Uuid::new_v4().to_string(); map.insert(ContextKey::CorrelationId.as_str().to_string(), Value::String(id.clone())); map.insert(ContextKey::RequestId.as_str().to_string(), Value::String(id.clone())); + // `traceId` seeds to a fabricated uuid — the FALLBACK. When an OpenTelemetry + // span is active at emit time, `Logger::build_log_object` overrides this with + // the span's real W3C trace_id (and adds `spanId`) via + // [`active_otel_trace_context`], so logs correlate to the trace they belong + // to. This uuid only surfaces when no span is active. (th-de3805) map.insert(ContextKey::TraceId.as_str().to_string(), Value::String(id)); map } +/// The active OpenTelemetry span's `(trace_id, span_id)` as W3C hex strings, or +/// `None` when no valid span is on the current [`opentelemetry::Context`]. +/// +/// Depends on the OpenTelemetry **API only** (never `@smooai/observability` — +/// that would be a circular dependency). When nothing set up an OTel context — +/// no tracer installed, or no span active — `Context::current()` yields an empty +/// context whose span is invalid, so callers fall back to prior behavior. +pub fn active_otel_trace_context() -> Option<(String, String)> { + use opentelemetry::trace::TraceContextExt; + let context = opentelemetry::Context::current(); + let span = context.span(); + let span_context = span.span_context(); + if span_context.is_valid() { + Some((span_context.trace_id().to_string(), span_context.span_id().to_string())) + } else { + None + } +} + fn with_global_context(func: F) -> R where F: FnOnce(&mut ContextMap) -> R, diff --git a/rust/logger/src/env.rs b/rust/logger/src/env.rs index f439e05f..7d12c92c 100644 --- a/rust/logger/src/env.rs +++ b/rust/logger/src/env.rs @@ -14,6 +14,21 @@ pub fn environment() -> Option { env::var("NODE_ENV").ok().filter(|value| MAIN_ENVIRONMENTS.contains(&value.as_str())) } +/// Whether logger lines should be teed to the `tracing` facade so the +/// `@smooai/observability` OTLP appender turns them into log records. +/// +/// Gated on the SAME enablement as the observability logs pipeline — no code +/// dependency on `@smooai/observability` (that would be circular), just the same +/// env contract: an observability endpoint is configured and the SDK isn't +/// disabled. When off, `emit` stays stdout-direct with zero `tracing` overhead. +pub fn otel_bridge_enabled() -> bool { + let disabled = matches!(env::var("SMOOAI_OBSERVABILITY_DISABLED"), Ok(v) if v == "1" || v.eq_ignore_ascii_case("true")); + if disabled { + return false; + } + env::var("SMOOAI_OBSERVABILITY_ENDPOINT").is_ok() || env::var("OTEL_EXPORTER_OTLP_LOGS_ENDPOINT").is_ok() +} + #[cfg(test)] mod tests { use super::*; diff --git a/rust/logger/src/logger.rs b/rust/logger/src/logger.rs index 0411e1d7..ea57f887 100644 --- a/rust/logger/src/logger.rs +++ b/rust/logger/src/logger.rs @@ -84,6 +84,11 @@ pub struct LoggerOptions { /// Optional override for the redact-keys list. When `None`, defaults from /// [`default_redact_keys`] are used. pub redact_keys: Option>, + /// Tee every emitted line to the `tracing` facade so the + /// `@smooai/observability` OTLP appender can turn it into a log record. When + /// `None`, defaults to [`crate::env::otel_bridge_enabled`] (the same + /// enablement as the observability logs pipeline). + pub otel_bridge: Option, } fn default_config_settings() -> HashMap { @@ -104,6 +109,7 @@ pub struct Logger { rotation: RotationOptions, file_writer: Option>, redact_keys: std::collections::HashSet, + otel_bridge: bool, } impl Default for Logger { @@ -161,6 +167,8 @@ impl Logger { .map(|k| k.to_lowercase()) .collect(); + let otel_bridge = options.otel_bridge.unwrap_or_else(crate::env::otel_bridge_enabled); + Self { name, level, @@ -171,6 +179,7 @@ impl Logger { rotation, file_writer, redact_keys, + otel_bridge, } } @@ -387,6 +396,15 @@ impl Logger { ); map.insert(ContextKey::Name.as_str().into(), Value::String(self.name.clone())); + // Correlate this line to the active trace: when an OpenTelemetry span is + // active, override the fabricated `traceId` with the span's real W3C + // trace_id and attach its `spanId`. No active span → the seeded uuid + // (prior behavior) stays. (th-de3805) + if let Some((trace_id, span_id)) = context::active_otel_trace_context() { + map.insert(ContextKey::TraceId.as_str().into(), Value::String(trace_id)); + map.insert(ContextKey::SpanId.as_str().into(), Value::String(span_id)); + } + remove_nulls(&mut payload); if let Some(config) = &self.context_config { @@ -418,8 +436,37 @@ impl Logger { Ok(()) } + /// Tee an already-built payload to the `tracing` facade so the + /// `@smooai/observability` OTLP appender (a `tracing_subscriber::Layer`) can + /// turn it into a log record — the message becomes the record body, the full + /// structured payload rides along as the `log` field (→ log attributes). The + /// event fires while the same OTel span is still active, so the appender's + /// SDK logger stamps the record's trace_id/span_id from the current context, + /// matching the `traceId`/`spanId` this crate already put in the payload. + /// + /// No-op unless `otel_bridge` is on (see [`crate::env::otel_bridge_enabled`]). + /// tracing's level is a compile-time constant, so we dispatch per level. + fn tee_to_tracing(&self, level: Level, payload: &Value) { + if !self.otel_bridge { + return; + } + let message = payload.get(ContextKey::Message.as_str()).and_then(Value::as_str).unwrap_or_default(); + let log = payload.to_string(); + const TARGET: &str = "smooai_logger"; + match level { + Level::Trace => tracing::trace!(target: TARGET, log = %log, "{message}"), + Level::Debug => tracing::debug!(target: TARGET, log = %log, "{message}"), + Level::Info => tracing::info!(target: TARGET, log = %log, "{message}"), + Level::Warn => tracing::warn!(target: TARGET, log = %log, "{message}"), + Level::Error => tracing::error!(target: TARGET, log = %log, "{message}"), + // tracing has no Fatal — map to ERROR and preserve the fatal level as a field. + Level::Fatal => tracing::error!(target: TARGET, log = %log, otel_level = "fatal", "{message}"), + } + } + fn do_log(&self, level: Level, args: LogArgs) -> io::Result<()> { let payload = self.build_log_object(level, &args); + self.tee_to_tracing(level, &payload); self.emit(payload) } diff --git a/rust/logger/tests/otel_correlation.rs b/rust/logger/tests/otel_correlation.rs new file mode 100644 index 00000000..d2f5fbaa --- /dev/null +++ b/rust/logger/tests/otel_correlation.rs @@ -0,0 +1,130 @@ +//! Log↔trace correlation + tracing-tee tests (th-de3805). +//! +//! Proves the two halves of the correlation fix: +//! 1. A log built while an OpenTelemetry span is active carries that span's +//! real W3C `traceId`/`spanId` (not a fabricated uuid); with no span active +//! it falls back to the seeded uuid and emits no `spanId`. +//! 2. With the OTel bridge enabled, each emitted line is teed to the `tracing` +//! facade (which `@smooai/observability`'s appender hooks) at the matching +//! level with the message as the body; disabled, nothing is teed. + +use std::sync::{Arc, Mutex}; + +use opentelemetry::trace::{TraceContextExt, Tracer, TracerProvider}; +use opentelemetry::Context; +use opentelemetry_sdk::trace::SdkTracerProvider; +use smooai_logger::{Level, LogArgs, Logger, LoggerOptions}; +use tracing::field::{Field, Visit}; +use tracing_subscriber::layer::{Context as LayerContext, Layer}; +use tracing_subscriber::prelude::*; + +fn test_logger(otel_bridge: bool) -> Logger { + Logger::new(LoggerOptions { + name: Some("test".into()), + log_to_file: Some(false), + otel_bridge: Some(otel_bridge), + ..Default::default() + }) +} + +#[test] +fn log_within_active_span_carries_real_trace_and_span_id() { + let logger = test_logger(false); + + let provider = SdkTracerProvider::builder().build(); + let tracer = provider.tracer("correlation-test"); + let cx = Context::current().with_span(tracer.start("unit-of-work")); + let span_context = cx.span().span_context().clone(); + assert!(span_context.is_valid(), "test span must be valid/sampled"); + + let payload = { + let _guard = cx.clone().attach(); + logger.build_log_object(Level::Info, &LogArgs::from("hello within span")) + }; + + assert_eq!( + payload.get("traceId").and_then(|v| v.as_str()), + Some(span_context.trace_id().to_string().as_str()), + "traceId must be the active span's real W3C trace_id, not a uuid" + ); + assert_eq!( + payload.get("spanId").and_then(|v| v.as_str()), + Some(span_context.span_id().to_string().as_str()), + "spanId must be the active span's real W3C span_id" + ); +} + +#[test] +fn log_without_active_span_falls_back_to_uuid() { + let logger = test_logger(false); + + // No span attached on this thread → the seeded uuid traceId, no spanId. + let payload = logger.build_log_object(Level::Info, &LogArgs::from("hello no span")); + + let trace_id = payload.get("traceId").and_then(|v| v.as_str()).expect("traceId present"); + // A uuid is 36 chars with hyphens; a W3C trace_id is 32 hex chars, no hyphens. + assert!(trace_id.contains('-'), "fallback traceId should be the fabricated uuid, got {trace_id}"); + assert!(payload.get("spanId").is_none(), "no active span → no spanId"); +} + +// ---- Tee-to-tracing capture ------------------------------------------------ + +#[derive(Default, Clone)] +struct Captured { + level: Option, + message: Option, +} + +struct MessageVisitor<'a>(&'a mut Captured); +impl Visit for MessageVisitor<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + self.0.message = Some(format!("{value:?}")); + } + } +} + +struct CaptureLayer(Arc>>); +impl Layer for CaptureLayer { + fn on_event(&self, event: &tracing::Event<'_>, _ctx: LayerContext<'_, S>) { + let mut cap = Captured { + level: Some(*event.metadata().level()), + ..Default::default() + }; + event.record(&mut MessageVisitor(&mut cap)); + self.0.lock().unwrap().push(cap); + } +} + +#[test] +fn enabled_bridge_tees_line_to_tracing() { + let events = Arc::new(Mutex::new(Vec::new())); + let subscriber = tracing_subscriber::registry().with(CaptureLayer(events.clone())); + + let logger = test_logger(true); + tracing::subscriber::with_default(subscriber, || { + logger.warn(LogArgs::from("teed message")).unwrap(); + }); + + let captured = events.lock().unwrap(); + assert_eq!(captured.len(), 1, "one line should tee to exactly one tracing event"); + assert_eq!(captured[0].level, Some(tracing::Level::WARN), "warn() must map to tracing WARN"); + assert_eq!( + captured[0].message.as_deref(), + Some("teed message"), + "the tracing event body must be the log message" + ); +} + +#[test] +fn disabled_bridge_does_not_tee() { + let events = Arc::new(Mutex::new(Vec::new())); + let subscriber = tracing_subscriber::registry().with(CaptureLayer(events.clone())); + + let logger = test_logger(false); + tracing::subscriber::with_default(subscriber, || { + logger.info(LogArgs::from("not teed")).unwrap(); + }); + + assert!(events.lock().unwrap().is_empty(), "disabled bridge must emit no tracing events"); +}