feat(otel): export logs through the tracing pipeline, correlated with traces (#147)
Logs were a separate pipeline: env_logger in debug (never exported) and opentelemetry-appender-log in release (exported without trace context, so SigNoz could not link logs to traces). - tracing-subscriber `tracing-log` feature: try_init installs LogTracer, so log:: records become tracing events: one console format, and RUST_LOG per-module directives still apply to them. - opentelemetry-appender-tracing exports events as OTel log records when OTLP_OTLS_ENDPOINT is set (any build), stamped with the enclosing span's trace_id/span_id. A per-layer filter drops the exporter's own crates. - The OTel span layer keeps only WARN/ERROR events as span events; the info/debug copies duplicated the correlated logs. - Remove env_logger init in the server, init_logs, and the unused opentelemetry-appender-log / opentelemetry-stdout deps. - tests/otel_log_correlation.rs pins correlation (native + bridged), the span-event filter, and per-module filtering of bridged records. - Constitution 1.2.0 (Principle V logging rule), CLAUDE.md, README, .env.example. Closes #147 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
1 parent
79b339a2a6
commit
3b3e6bdb39
9 files changed
+284
-106
No files matched your search
@@ -0,0 +1,167 @@
|
||||
//! Log records exported through the `tracing` pipeline (#147): they carry
|
||||
//! the trace_id / span_id of the span they were emitted in — for native
|
||||
//! `tracing` macros AND for `log::` records bridged via `LogTracer` — and
|
||||
//! the span layer keeps only WARN/ERROR events as span events.
|
||||
//!
|
||||
//! Mirrors the layer stack in `otel::init_tracing`, with in-memory exporters
|
||||
//! in place of OTLP.
|
||||
|
||||
use image_api::otel::span_layer_filter;
|
||||
use opentelemetry::trace::{TraceContextExt, TracerProvider};
|
||||
use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
|
||||
use opentelemetry_sdk::logs::{InMemoryLogExporter, SdkLoggerProvider};
|
||||
use opentelemetry_sdk::trace::{InMemorySpanExporter, SdkTracerProvider};
|
||||
use tracing_opentelemetry::OpenTelemetrySpanExt;
|
||||
use tracing_subscriber::Layer;
|
||||
use tracing_subscriber::layer::SubscriberExt;
|
||||
|
||||
struct Harness {
|
||||
logs: InMemoryLogExporter,
|
||||
spans: InMemorySpanExporter,
|
||||
tracer_provider: SdkTracerProvider,
|
||||
}
|
||||
|
||||
impl Harness {
|
||||
fn run<R>(filter: &str, f: impl FnOnce() -> R) -> (Self, R) {
|
||||
// The global LogTracer forwards `log` records to the *current*
|
||||
// dispatcher, so each scoped subscriber below receives them.
|
||||
let _ = tracing_log::LogTracer::init();
|
||||
|
||||
let logs = InMemoryLogExporter::default();
|
||||
let logger_provider = SdkLoggerProvider::builder()
|
||||
.with_simple_exporter(logs.clone())
|
||||
.build();
|
||||
let spans = InMemorySpanExporter::default();
|
||||
let tracer_provider = SdkTracerProvider::builder()
|
||||
.with_simple_exporter(spans.clone())
|
||||
.build();
|
||||
let tracer = tracer_provider.tracer("test");
|
||||
|
||||
let subscriber = tracing_subscriber::registry()
|
||||
.with(tracing_subscriber::EnvFilter::new(filter))
|
||||
.with(
|
||||
tracing_opentelemetry::OpenTelemetryLayer::new(tracer)
|
||||
.with_filter(span_layer_filter()),
|
||||
)
|
||||
.with(OpenTelemetryTracingBridge::new(&logger_provider));
|
||||
let out = tracing::subscriber::with_default(subscriber, f);
|
||||
(
|
||||
Harness {
|
||||
logs,
|
||||
spans,
|
||||
tracer_provider,
|
||||
},
|
||||
out,
|
||||
)
|
||||
}
|
||||
|
||||
fn log_bodies(&self) -> Vec<String> {
|
||||
self.logs
|
||||
.get_emitted_logs()
|
||||
.expect("logs")
|
||||
.iter()
|
||||
.map(|l| format!("{:?}", l.record.body()))
|
||||
.collect()
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn log_records_carry_span_trace_context() {
|
||||
let (h, (trace_id, span_id, child_span_id)) = Harness::run("info", || {
|
||||
tracing::info!("outside");
|
||||
let span = tracing::info_span!("parent");
|
||||
let _g = span.enter();
|
||||
tracing::info!("tracing inside");
|
||||
log::info!("log inside");
|
||||
let child = tracing::info_span!("child");
|
||||
let child_id = {
|
||||
let _c = child.enter();
|
||||
tracing::warn!("tracing in child");
|
||||
child.context().span().span_context().span_id()
|
||||
};
|
||||
let ctx = span.context();
|
||||
let span_ref = ctx.span();
|
||||
let sc = span_ref.span_context();
|
||||
(sc.trace_id(), sc.span_id(), child_id)
|
||||
});
|
||||
|
||||
let logs = h.logs.get_emitted_logs().expect("logs");
|
||||
let find = |body: &str| {
|
||||
logs.iter()
|
||||
.find(|l| format!("{:?}", l.record.body()).contains(body))
|
||||
.unwrap_or_else(|| panic!("no record with body {body}"))
|
||||
};
|
||||
|
||||
assert!(find("outside").record.trace_context().is_none());
|
||||
|
||||
for body in ["tracing inside", "log inside"] {
|
||||
let tc = find(body).record.trace_context().expect(body);
|
||||
assert_eq!(tc.trace_id, trace_id, "{body}");
|
||||
assert_eq!(tc.span_id, span_id, "{body}");
|
||||
}
|
||||
|
||||
let tc = find("tracing in child")
|
||||
.record
|
||||
.trace_context()
|
||||
.expect("child");
|
||||
assert_eq!(tc.trace_id, trace_id);
|
||||
assert_eq!(tc.span_id, child_span_id);
|
||||
|
||||
// Bridged records keep their module in code.namespace (the bridge's
|
||||
// own target is the fixed "log").
|
||||
let namespace = find("log inside")
|
||||
.record
|
||||
.attributes_iter()
|
||||
.find(|(k, _)| k.as_str() == "code.namespace")
|
||||
.map(|(_, v)| format!("{v:?}"));
|
||||
assert!(
|
||||
namespace.is_some_and(|ns| ns.contains("otel_log_correlation")),
|
||||
"bridged record lost its module"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn span_events_keep_only_warn_and_error() {
|
||||
let (h, ()) = Harness::run("info", || {
|
||||
let span = tracing::info_span!("parent");
|
||||
let _g = span.enter();
|
||||
tracing::info!("info event");
|
||||
tracing::warn!("warn event");
|
||||
tracing::error!("error event");
|
||||
});
|
||||
h.tracer_provider.force_flush().expect("flush");
|
||||
|
||||
let spans = h.spans.get_finished_spans().expect("spans");
|
||||
let parent = spans.iter().find(|s| s.name == "parent").expect("parent");
|
||||
let names: Vec<String> = parent.events.iter().map(|e| e.name.to_string()).collect();
|
||||
assert_eq!(names, vec!["warn event", "error event"]);
|
||||
|
||||
// The info event is still exported as a (correlated) log record.
|
||||
assert!(h.log_bodies().iter().any(|b| b.contains("info event")));
|
||||
}
|
||||
|
||||
/// Per-module `RUST_LOG` directives must still reach bridged `log::`
|
||||
/// records, as they did under env_logger.
|
||||
#[test]
|
||||
fn per_module_directives_apply_to_bridged_log_records() {
|
||||
let (h, ()) = Harness::run("info,otel_log_correlation=debug", || {
|
||||
log::debug!("bridged debug");
|
||||
tracing::debug!("native debug");
|
||||
});
|
||||
let bodies = h.log_bodies();
|
||||
assert!(
|
||||
bodies.iter().any(|b| b.contains("native debug")),
|
||||
"{bodies:?}"
|
||||
);
|
||||
assert!(
|
||||
bodies.iter().any(|b| b.contains("bridged debug")),
|
||||
"{bodies:?}"
|
||||
);
|
||||
|
||||
// ...and without the directive, the same records are filtered out.
|
||||
let (h, ()) = Harness::run("info", || {
|
||||
log::debug!("bridged debug");
|
||||
tracing::debug!("native debug");
|
||||
});
|
||||
assert!(h.log_bodies().is_empty(), "{:?}", h.log_bodies());
|
||||
}
|
||||
Reference in new issue
Block a user