feat(otel): export logs through the tracing pipeline, correlated with traces (#147) #155
No files matched your search
+3
-2
@@ -32,8 +32,9 @@ HLS_TIMEOUT_SECONDS=900
|
||||
PLAYLIST_CLEANUP_INTERVAL_SECONDS=86400
|
||||
|
||||
# ── Telemetry ────────────────────────────────────────────────────────────
|
||||
# Span export over OTLP in any build when set (unset = spans stay local).
|
||||
# RUST_LOG also gates span export: keep it at info or debug.
|
||||
# Span + log export over OTLP in any build when set (unset = nothing
|
||||
# exported). Logs carry trace ids, so SigNoz links them to traces.
|
||||
# RUST_LOG also gates export: keep it at info or debug.
|
||||
# OTLP_OTLS_ENDPOINT=http://localhost:4317
|
||||
|
||||
# ── AI Insights — Ollama (local LLM) ────────────────────────────────────
|
||||
|
||||
@@ -1,17 +1,15 @@
|
||||
<!--
|
||||
Sync Impact Report
|
||||
==================
|
||||
Version change: 1.0.0 -> 1.1.0
|
||||
Bump rationale: MINOR. Principle V is materially expanded: the tracing
|
||||
mechanism changed (tracing + tracing-opentelemetry in every build), and
|
||||
it adds two new MUST rules: no manual Context threading, and carrying
|
||||
the parent span across spawns. No principle is removed or redefined in
|
||||
intent.
|
||||
Version change: 1.1.0 -> 1.2.0
|
||||
Bump rationale: MINOR. Principle V's logging rule is materially changed:
|
||||
logs are no longer a separate, build-profile-dependent pipeline; they
|
||||
share the tracing subscriber and export correlated with traces in any
|
||||
build (#147). No principle is removed or redefined in intent.
|
||||
Modified principles:
|
||||
- V. Observability: mechanism + rules updated for the tracing migration
|
||||
(map #135, PR #148)
|
||||
- V. Observability: logging bullet rewritten; span events limited to
|
||||
WARN/ERROR
|
||||
Also updated:
|
||||
- I. Layered Architecture: Database Layer "traced" wording
|
||||
- Technology Stack & Constraints: Tracing line
|
||||
Added sections: N/A
|
||||
Removed sections: N/A
|
||||
@@ -22,11 +20,11 @@
|
||||
- .specify/templates/checklist-template.md — ✅ no changes needed
|
||||
- .specify/templates/agent-file-template.md — ✅ no changes needed
|
||||
Runtime guidance:
|
||||
- CLAUDE.md "Tracing" — ✅ already consistent (conventions landed with #148);
|
||||
OTLP env line + dependency list updated alongside this amendment
|
||||
- README.md — ✅ RUST_LOG default/gating corrected; OTLP_OTLS_ENDPOINT added
|
||||
- .env.example — ✅ telemetry header corrected
|
||||
Follow-up TODOs: None
|
||||
- CLAUDE.md "Tracing" — ✅ logs bullet added; dependency list updated
|
||||
- README.md — ✅ RUST_LOG default + OTLP_OTLS_ENDPOINT now cover logs
|
||||
- .env.example — ✅ telemetry header covers logs
|
||||
Follow-up TODOs: migrate `log::` macros to `tracing::` (bridged records
|
||||
export with target "log"; module survives only in code.namespace)
|
||||
-->
|
||||
|
||||
# ImageApi Constitution
|
||||
@@ -113,8 +111,11 @@ All database operations and HTTP handlers MUST be instrumented with
|
||||
an uncarried spawn orphans its spans onto a fresh trace.
|
||||
- `RUST_LOG` gates span export as well as console output (one `EnvFilter`).
|
||||
Deployments MUST run at `info` or `debug`.
|
||||
- Logs are a separate pipeline: `env_logger` in debug, OTel log export in
|
||||
release.
|
||||
- Logs share the tracing subscriber: `log::` records are bridged into
|
||||
`tracing`, so both print in one console format. With
|
||||
`OTLP_OTLS_ENDPOINT` set (any build), events export as OTel log records
|
||||
carrying the enclosing span's trace_id / span_id. Only WARN and ERROR
|
||||
events are also recorded on spans as span events.
|
||||
- Prometheus metrics (`imageserver_image_total`,
|
||||
`imageserver_video_total`) MUST be maintained for key counters.
|
||||
- Errors MUST be logged at `error!` level with sufficient context
|
||||
@@ -136,8 +137,8 @@ job in one trace by construction.
|
||||
- **Image Processing**: `image` crate for thumbnails, `kamadak-exif`
|
||||
for EXIF extraction
|
||||
- **Tracing**: `tracing` + `tracing-opentelemetry` (every build), OTLP
|
||||
export when `OTLP_OTLS_ENDPOINT` is set; logs via `env_logger` (debug) /
|
||||
OTel log export (release)
|
||||
export when `OTLP_OTLS_ENDPOINT` is set; logs through the same
|
||||
subscriber via `opentelemetry-appender-tracing` (`log::` bridged)
|
||||
- **Testing**: `cargo test`, `actix_web::test`, in-memory SQLite
|
||||
|
||||
External dependencies (ffmpeg, Ollama) are optional runtime
|
||||
@@ -177,4 +178,4 @@ MUST comply with these principles.
|
||||
these principles. The CLAUDE.md file provides runtime development
|
||||
guidance and MUST remain consistent with this constitution.
|
||||
|
||||
**Version**: 1.1.0 | **Ratified**: 2026-02-26 | **Last Amended**: 2026-09-29
|
||||
**Version**: 1.2.0 | **Ratified**: 2026-02-26 | **Last Amended**: 2026-09-29
|
||||
@@ -593,6 +593,14 @@ an incoming `traceparent`). Conventions:
|
||||
never hold `span.enter()` across an `.await`.
|
||||
- DB: `otel::trace_db_call`; LLM: `otel::start_llm_request_span` (injects
|
||||
`traceparent` downstream).
|
||||
- **Logs ride the same subscriber.** `log::` records are bridged into
|
||||
`tracing` (the `tracing-log` feature), so there's one console format, and
|
||||
with `OTLP_OTLS_ENDPOINT` set every event is exported as an OTel log record
|
||||
stamped with its span's trace_id / span_id (`opentelemetry-appender-tracing`)
|
||||
— SigNoz links logs to traces. Prefer `tracing::` macros in new code:
|
||||
bridged records export with target `log` (module only in `code.namespace`).
|
||||
The span layer keeps only WARN/ERROR events as span events (error events
|
||||
set span status); `tests/otel_log_correlation.rs` pins all of this.
|
||||
- **`RUST_LOG` gates spans, not just logs.** The subscriber's single
|
||||
`EnvFilter` sits in front of both the console and the OTel layer, so a span
|
||||
below the filter level is never created: it's missing from the export, it
|
||||
@@ -956,7 +964,7 @@ side if exposing beyond a trusted network.
|
||||
- **image**: Thumbnail generation
|
||||
- **walkdir**: Directory traversal
|
||||
- **rayon**: Parallel processing
|
||||
- **tracing** + **tracing-opentelemetry** + **tracing-actix-web**: spans (exported via `opentelemetry-otlp`)
|
||||
- **tracing** + **tracing-opentelemetry** + **tracing-actix-web**: spans (exported via `opentelemetry-otlp`); logs via **opentelemetry-appender-tracing**
|
||||
- **bcrypt**: Password hashing
|
||||
- **infer**: Magic number file type detection
|
||||
|
||||
|
||||
Generated
+11
-17
@@ -2107,9 +2107,8 @@ dependencies = [
|
||||
"libsqlite3-sys",
|
||||
"log",
|
||||
"opentelemetry",
|
||||
"opentelemetry-appender-log",
|
||||
"opentelemetry-appender-tracing",
|
||||
"opentelemetry-otlp",
|
||||
"opentelemetry-stdout",
|
||||
"opentelemetry_sdk",
|
||||
"path-absolutize",
|
||||
"prometheus",
|
||||
@@ -2125,6 +2124,7 @@ dependencies = [
|
||||
"tokio-util",
|
||||
"tracing",
|
||||
"tracing-actix-web",
|
||||
"tracing-log",
|
||||
"tracing-opentelemetry",
|
||||
"tracing-subscriber",
|
||||
"tzf-rs",
|
||||
@@ -2759,13 +2759,17 @@ dependencies = [
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "opentelemetry-appender-log"
|
||||
version = "0.31.0"
|
||||
name = "opentelemetry-appender-tracing"
|
||||
version = "0.31.1"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "9e50c59a96bd6a723a4329c5db31eb04fa4488c5f141ae7b9d4fd587439e6ee1"
|
||||
checksum = "ef6a1ac5ca3accf562b8c306fa8483c85f4390f768185ab775f242f7fe8fdcc2"
|
||||
dependencies = [
|
||||
"log",
|
||||
"opentelemetry",
|
||||
"tracing",
|
||||
"tracing-core",
|
||||
"tracing-log",
|
||||
"tracing-opentelemetry",
|
||||
"tracing-subscriber",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
@@ -2813,17 +2817,6 @@ dependencies = [
|
||||
"tonic-prost",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "opentelemetry-stdout"
|
||||
version = "0.31.0"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "bc8887887e169414f637b18751487cce4e095be787d23fad13c454e2fb1b3811"
|
||||
dependencies = [
|
||||
"chrono",
|
||||
"opentelemetry",
|
||||
"opentelemetry_sdk",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "opentelemetry_sdk"
|
||||
version = "0.31.0"
|
||||
@@ -4443,6 +4436,7 @@ dependencies = [
|
||||
"thread_local",
|
||||
"tracing",
|
||||
"tracing-core",
|
||||
"tracing-log",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
|
||||
+8
-6
@@ -39,11 +39,11 @@ rayon = "1.5"
|
||||
path-absolutize = "3.1"
|
||||
log = "0.4"
|
||||
env_logger = "0.11.5"
|
||||
# default-features = false keeps the `tracing-log` bridge OFF so the console
|
||||
# fmt layer prints tracing spans only; `log` records stay on their existing
|
||||
# path (env_logger in debug, OTel logs in release) without double-printing.
|
||||
# `tracing-log` is ON: `try_init` installs the LogTracer bridge, so `log::`
|
||||
# records become tracing events and share the one console format + OTel
|
||||
# log export (#147 spike).
|
||||
tracing = "0.1"
|
||||
tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "env-filter", "fmt", "ansi"] }
|
||||
tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "env-filter", "fmt", "ansi", "tracing-log"] }
|
||||
tracing-opentelemetry = "0.32"
|
||||
tracing-actix-web = { version = "0.7", features = ["opentelemetry_0_31"] }
|
||||
actix-web-prom = "0.9.0"
|
||||
@@ -54,8 +54,6 @@ rand = "0.8.5"
|
||||
opentelemetry = { version = "0.31.0", features = ["default", "metrics", "tracing"] }
|
||||
opentelemetry_sdk = { version = "0.31.0", features = ["default", "rt-tokio-current-thread", "metrics", "testing"] }
|
||||
opentelemetry-otlp = { version = "0.31.0", features = ["default", "metrics", "tracing", "grpc-tonic"] }
|
||||
opentelemetry-stdout = "0.31.0"
|
||||
opentelemetry-appender-log = "0.31.0"
|
||||
tempfile = "3.20.0"
|
||||
regex = "1.11.1"
|
||||
exif = { package = "kamadak-exif", version = "0.6.1" }
|
||||
@@ -76,8 +74,12 @@ indicatif = "0.17"
|
||||
uuid = { version = "1.10", features = ["v4", "serde"] }
|
||||
chrono-tz = "0.10"
|
||||
tzf-rs = "2.1.2"
|
||||
opentelemetry-appender-tracing = { version = "0.31", features = ["experimental_use_tracing_span_context", "experimental_metadata_attributes"] }
|
||||
|
||||
# Windows lacks system sqlite3, so re-enable the bundled C build there.
|
||||
# Linux/macOS use the system library (faster builds, smaller binary).
|
||||
[target.'cfg(windows)'.dependencies]
|
||||
libsqlite3-sys = { version = "0.35", features = ["bundled"] }
|
||||
|
||||
[dev-dependencies]
|
||||
tracing-log = "0.2"
|
||||
@@ -73,8 +73,8 @@ They should be defined where the binary is located or above it in an `.env` file
|
||||
- `BIND_URL` is the url and port to bind to (typically your own IP address)
|
||||
- `LOCAL_BIND_URL` (optional) is a second, loopback listener [default: `localhost:8088`]. Set it to an empty string to skip it, e.g. to run a second instance such as the `dev/e2e` harness alongside one that already owns 8088
|
||||
- `SECRET_KEY` is the *hopefully* random string to sign Tokens with
|
||||
- `RUST_LOG` is one of `off, error, warn, info, debug, trace`, from least to most noisy [default: `info` for spans, `error` for dev console logs]. It also gates tracing-span export, so keep it at `info` or `debug`
|
||||
- `OTLP_OTLS_ENDPOINT` (optional) is an OTLP/gRPC collector URL (e.g. SigNoz, Jaeger) for span export, in any build [default: unset, no export]
|
||||
- `RUST_LOG` is one of `off, error, warn, info, debug, trace`, from least to most noisy [default: `info`]. It gates console output, span export and log export alike, so keep it at `info` or `debug`
|
||||
- `OTLP_OTLS_ENDPOINT` (optional) is an OTLP/gRPC collector URL (e.g. SigNoz, Jaeger) for span and log export (logs carry trace ids, so they link to traces), in any build [default: unset, no export]
|
||||
- `EXCLUDED_DIRS` is a comma separated list of directories to exclude from the Memories API
|
||||
- `PREVIEW_CLIPS_DIRECTORY` (optional) is a path where generated video preview clips should be stored [default: `preview_clips`]
|
||||
- `WATCH_QUICK_INTERVAL_SECONDS` (optional) is the interval in seconds for quick file scans [default: 60]
|
||||
|
||||
+3
-11
@@ -111,17 +111,9 @@ fn main() -> std::io::Result<()> {
|
||||
let system = actix::System::new();
|
||||
system.block_on(async {
|
||||
// One `tracing` subscriber in every build: env-driven, so dev prints
|
||||
// spans to the console and release exports them over OTLP. The `log`
|
||||
// pipeline stays separate — env_logger in debug, OTel logs in release.
|
||||
otel::init_tracing();
|
||||
#[cfg(debug_assertions)]
|
||||
{
|
||||
env_logger::init();
|
||||
}
|
||||
#[cfg(not(debug_assertions))]
|
||||
{
|
||||
otel::init_logs();
|
||||
}
|
||||
// spans + logs to the console and OTLP_OTLS_ENDPOINT exports both.
|
||||
// `log::` records are bridged into it.
|
||||
let _logger_provider = otel::init_tracing();
|
||||
|
||||
// AppState construction loads (and seeds if needed) the libraries
|
||||
// table; we use that list to drive the initial thumbnail sweep.
|
||||
|
||||
+61
-48
@@ -1,29 +1,33 @@
|
||||
use opentelemetry::propagation::TextMapPropagator;
|
||||
use opentelemetry::trace::{Status, TraceContextExt, TracerProvider};
|
||||
use opentelemetry::{Context, KeyValue, global};
|
||||
use opentelemetry_appender_log::OpenTelemetryLogBridge;
|
||||
use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
|
||||
use opentelemetry_otlp::WithExportConfig;
|
||||
use opentelemetry_sdk::Resource;
|
||||
use opentelemetry_sdk::logs::{BatchLogProcessor, SdkLoggerProvider};
|
||||
use opentelemetry_sdk::logs::SdkLoggerProvider;
|
||||
use opentelemetry_sdk::propagation::TraceContextPropagator;
|
||||
use tracing_subscriber::Layer;
|
||||
use tracing_subscriber::layer::SubscriberExt;
|
||||
use tracing_subscriber::util::SubscriberInitExt;
|
||||
|
||||
/// Install the process-wide `tracing` subscriber plus the OTel span pipeline.
|
||||
/// Install the process-wide `tracing` subscriber plus the OTel span and log
|
||||
/// pipelines.
|
||||
///
|
||||
/// Called in BOTH debug and release builds (the old split made spans a no-op
|
||||
/// in dev). Behaviour is driven by the environment, not the build profile:
|
||||
/// - `OTLP_OTLS_ENDPOINT` set -> spans are batch-exported over OTLP (the
|
||||
/// release / staging path).
|
||||
/// - unset -> spans are created with valid contexts (so
|
||||
/// outgoing `traceparent` injection still works) but exported nowhere; the
|
||||
/// console `fmt` layer is what shows them.
|
||||
/// One subscriber handles everything, in every build; behaviour comes from
|
||||
/// the environment, not the build profile:
|
||||
/// - `OTLP_OTLS_ENDPOINT` set -> spans AND log records are batch-exported
|
||||
/// over OTLP. Log records carry the trace_id / span_id of the span they
|
||||
/// were emitted in, so SigNoz correlates logs with traces.
|
||||
/// - unset -> spans get valid contexts (outgoing
|
||||
/// `traceparent` injection still works) but nothing is exported.
|
||||
///
|
||||
/// The console `fmt` layer is always present, so a release build run locally
|
||||
/// also prints spans to stdout. `log` records are NOT routed through this
|
||||
/// subscriber (the `tracing-log` bridge is off) — they keep their existing
|
||||
/// path: `env_logger` in debug, OTel logs in release.
|
||||
pub fn init_tracing() {
|
||||
/// The console `fmt` layer is always present. `log::` records are bridged
|
||||
/// into `tracing` (the `tracing-log` feature makes `try_init` install
|
||||
/// `LogTracer`), so they print in the same format and export the same way.
|
||||
///
|
||||
/// Returns the logger provider when log export is on; the caller keeps it
|
||||
/// alive and calls `shutdown()` on exit to flush the batch.
|
||||
pub fn init_tracing() -> Option<SdkLoggerProvider> {
|
||||
// W3C propagator for the whole process: the request middleware
|
||||
// (tracing-actix-web) and the outgoing `traceparent` helpers both read
|
||||
// the *global* propagator, so it must be set before any request lands.
|
||||
@@ -36,10 +40,11 @@ pub fn init_tracing() {
|
||||
])
|
||||
.build();
|
||||
|
||||
let mut provider_builder =
|
||||
opentelemetry_sdk::trace::SdkTracerProvider::builder().with_resource(resources);
|
||||
let endpoint = std::env::var("OTLP_OTLS_ENDPOINT").ok();
|
||||
|
||||
if let Ok(endpoint) = std::env::var("OTLP_OTLS_ENDPOINT") {
|
||||
let mut provider_builder =
|
||||
opentelemetry_sdk::trace::SdkTracerProvider::builder().with_resource(resources.clone());
|
||||
if let Some(endpoint) = &endpoint {
|
||||
let span_exporter = opentelemetry_otlp::SpanExporter::builder()
|
||||
.with_tonic()
|
||||
.with_endpoint(endpoint)
|
||||
@@ -55,7 +60,27 @@ pub fn init_tracing() {
|
||||
let tracer = tracer_provider.tracer("image-server");
|
||||
global::set_tracer_provider(tracer_provider);
|
||||
|
||||
// One EnvFilter in front of BOTH layers: `RUST_LOG` also decides which
|
||||
let logger_provider = endpoint.map(|endpoint| {
|
||||
let log_exporter = opentelemetry_otlp::LogExporter::builder()
|
||||
.with_tonic()
|
||||
.with_endpoint(endpoint)
|
||||
.build()
|
||||
.expect("OTLP log exporter");
|
||||
SdkLoggerProvider::builder()
|
||||
.with_batch_exporter(log_exporter)
|
||||
.with_resource(resources)
|
||||
.build()
|
||||
});
|
||||
|
||||
// The exporter's own crates log through `tracing` too; exporting those
|
||||
// records would feed back into the exporter, so this layer drops them.
|
||||
let log_layer = logger_provider.as_ref().map(|provider| {
|
||||
OpenTelemetryTracingBridge::new(provider).with_filter(tracing_subscriber::EnvFilter::new(
|
||||
"trace,opentelemetry=off,opentelemetry_sdk=off,opentelemetry_otlp=off,tonic=off,h2=off,hyper=off,tower=off",
|
||||
))
|
||||
});
|
||||
|
||||
// One EnvFilter in front of every layer: `RUST_LOG` also decides which
|
||||
// spans exist for export. All spans are `info`, so keep it at info/debug
|
||||
// (see CLAUDE.md "Tracing"); `warn` turns span export off.
|
||||
tracing_subscriber::registry()
|
||||
@@ -63,39 +88,27 @@ pub fn init_tracing() {
|
||||
tracing_subscriber::EnvFilter::try_from_default_env()
|
||||
.unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")),
|
||||
)
|
||||
.with(tracing_opentelemetry::OpenTelemetryLayer::new(tracer))
|
||||
.with(tracing_subscriber::fmt::layer().with_target(false))
|
||||
.with(
|
||||
tracing_opentelemetry::OpenTelemetryLayer::new(tracer).with_filter(span_layer_filter()),
|
||||
)
|
||||
.with(log_layer)
|
||||
.with(tracing_subscriber::fmt::layer())
|
||||
.try_init()
|
||||
.expect("failed to install tracing subscriber");
|
||||
|
||||
logger_provider
|
||||
}
|
||||
|
||||
#[allow(dead_code)]
|
||||
pub fn init_logs() {
|
||||
let otlp_exporter = opentelemetry_otlp::LogExporter::builder()
|
||||
.with_tonic()
|
||||
.with_endpoint(std::env::var("OTLP_OTLS_ENDPOINT").unwrap())
|
||||
.build()
|
||||
.unwrap();
|
||||
|
||||
let exporter = opentelemetry_stdout::LogExporter::default();
|
||||
|
||||
let resources = Resource::builder()
|
||||
.with_attributes([
|
||||
KeyValue::new("service.name", "image-server"),
|
||||
KeyValue::new("service.version", env!("CARGO_PKG_VERSION")),
|
||||
])
|
||||
.build();
|
||||
|
||||
let log_provider = SdkLoggerProvider::builder()
|
||||
.with_log_processor(BatchLogProcessor::builder(exporter).build())
|
||||
.with_log_processor(BatchLogProcessor::builder(otlp_exporter).build())
|
||||
.with_resource(resources)
|
||||
.build();
|
||||
|
||||
let otel_log_appender = OpenTelemetryLogBridge::new(&log_provider);
|
||||
log::set_boxed_logger(Box::new(otel_log_appender)).expect("Unable to set boxed logger");
|
||||
//TODO: Still set this with the env? Ideally we still have a clean/simple local logger for local dev
|
||||
log::set_max_level(log::LevelFilter::Info);
|
||||
/// Per-layer filter for the OTel span layer: every span, but only WARN and
|
||||
/// ERROR events. `tracing-opentelemetry` copies each event it sees onto its
|
||||
/// span as a span event; with logs exported and correlated separately, the
|
||||
/// info/debug copies are duplicate noise in the trace view. WARN/ERROR stay
|
||||
/// because error events set the span's status.
|
||||
pub fn span_layer_filter()
|
||||
-> tracing_subscriber::filter::FilterFn<impl Fn(&tracing::Metadata<'_>) -> bool> {
|
||||
tracing_subscriber::filter::filter_fn(|meta| {
|
||||
meta.is_span() || *meta.level() <= tracing::Level::WARN
|
||||
})
|
||||
}
|
||||
|
||||
/// Start a client span for a single LLM call. Every provider funnels its
|
||||
|
||||
@@ -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