feat(otel): export logs through the tracing pipeline, correlated with traces (#147) #155

Merged
cameron merged 1 commits from feature/tracing-log-export into master 2026-09-30 03:03:18 +00:00
9 changed files with 284 additions and 106 deletions

No files matched your search

+3 -2
View File
@@ -32,8 +32,9 @@ HLS_TIMEOUT_SECONDS=900
PLAYLIST_CLEANUP_INTERVAL_SECONDS=86400 PLAYLIST_CLEANUP_INTERVAL_SECONDS=86400
# ── Telemetry ──────────────────────────────────────────────────────────── # ── Telemetry ────────────────────────────────────────────────────────────
# Span export over OTLP in any build when set (unset = spans stay local). # Span + log export over OTLP in any build when set (unset = nothing
# RUST_LOG also gates span export: keep it at info or debug. # 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 # OTLP_OTLS_ENDPOINT=http://localhost:4317
# ── AI Insights — Ollama (local LLM) ──────────────────────────────────── # ── AI Insights — Ollama (local LLM) ────────────────────────────────────
+20 -19
View File
@@ -1,17 +1,15 @@
<!-- <!--
Sync Impact Report Sync Impact Report
================== ==================
Version change: 1.0.0 -> 1.1.0 Version change: 1.1.0 -> 1.2.0
Bump rationale: MINOR. Principle V is materially expanded: the tracing Bump rationale: MINOR. Principle V's logging rule is materially changed:
mechanism changed (tracing + tracing-opentelemetry in every build), and logs are no longer a separate, build-profile-dependent pipeline; they
it adds two new MUST rules: no manual Context threading, and carrying share the tracing subscriber and export correlated with traces in any
the parent span across spawns. No principle is removed or redefined in build (#147). No principle is removed or redefined in intent.
intent.
Modified principles: Modified principles:
- V. Observability: mechanism + rules updated for the tracing migration - V. Observability: logging bullet rewritten; span events limited to
(map #135, PR #148) WARN/ERROR
Also updated: Also updated:
- I. Layered Architecture: Database Layer "traced" wording
- Technology Stack & Constraints: Tracing line - Technology Stack & Constraints: Tracing line
Added sections: N/A Added sections: N/A
Removed sections: N/A Removed sections: N/A
@@ -22,11 +20,11 @@
- .specify/templates/checklist-template.md — ✅ no changes needed - .specify/templates/checklist-template.md — ✅ no changes needed
- .specify/templates/agent-file-template.md — ✅ no changes needed - .specify/templates/agent-file-template.md — ✅ no changes needed
Runtime guidance: Runtime guidance:
- CLAUDE.md "Tracing" — ✅ already consistent (conventions landed with #148); - CLAUDE.md "Tracing" — ✅ logs bullet added; dependency list updated
OTLP env line + dependency list updated alongside this amendment - README.md — ✅ RUST_LOG default + OTLP_OTLS_ENDPOINT now cover logs
- README.md — ✅ RUST_LOG default/gating corrected; OTLP_OTLS_ENDPOINT added - .env.example — ✅ telemetry header covers logs
- .env.example — ✅ telemetry header corrected Follow-up TODOs: migrate `log::` macros to `tracing::` (bridged records
Follow-up TODOs: None export with target "log"; module survives only in code.namespace)
--> -->
# ImageApi Constitution # 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. an uncarried spawn orphans its spans onto a fresh trace.
- `RUST_LOG` gates span export as well as console output (one `EnvFilter`). - `RUST_LOG` gates span export as well as console output (one `EnvFilter`).
Deployments MUST run at `info` or `debug`. Deployments MUST run at `info` or `debug`.
- Logs are a separate pipeline: `env_logger` in debug, OTel log export in - Logs share the tracing subscriber: `log::` records are bridged into
release. `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`, - Prometheus metrics (`imageserver_image_total`,
`imageserver_video_total`) MUST be maintained for key counters. `imageserver_video_total`) MUST be maintained for key counters.
- Errors MUST be logged at `error!` level with sufficient context - 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` - **Image Processing**: `image` crate for thumbnails, `kamadak-exif`
for EXIF extraction for EXIF extraction
- **Tracing**: `tracing` + `tracing-opentelemetry` (every build), OTLP - **Tracing**: `tracing` + `tracing-opentelemetry` (every build), OTLP
export when `OTLP_OTLS_ENDPOINT` is set; logs via `env_logger` (debug) / export when `OTLP_OTLS_ENDPOINT` is set; logs through the same
OTel log export (release) subscriber via `opentelemetry-appender-tracing` (`log::` bridged)
- **Testing**: `cargo test`, `actix_web::test`, in-memory SQLite - **Testing**: `cargo test`, `actix_web::test`, in-memory SQLite
External dependencies (ffmpeg, Ollama) are optional runtime 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 these principles. The CLAUDE.md file provides runtime development
guidance and MUST remain consistent with this constitution. 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
+9 -1
View File
@@ -593,6 +593,14 @@ an incoming `traceparent`). Conventions:
never hold `span.enter()` across an `.await`. never hold `span.enter()` across an `.await`.
- DB: `otel::trace_db_call`; LLM: `otel::start_llm_request_span` (injects - DB: `otel::trace_db_call`; LLM: `otel::start_llm_request_span` (injects
`traceparent` downstream). `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 - **`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 `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 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 - **image**: Thumbnail generation
- **walkdir**: Directory traversal - **walkdir**: Directory traversal
- **rayon**: Parallel processing - **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 - **bcrypt**: Password hashing
- **infer**: Magic number file type detection - **infer**: Magic number file type detection
Generated
+11 -17
View File
@@ -2107,9 +2107,8 @@ dependencies = [
"libsqlite3-sys", "libsqlite3-sys",
"log", "log",
"opentelemetry", "opentelemetry",
"opentelemetry-appender-log", "opentelemetry-appender-tracing",
"opentelemetry-otlp", "opentelemetry-otlp",
"opentelemetry-stdout",
"opentelemetry_sdk", "opentelemetry_sdk",
"path-absolutize", "path-absolutize",
"prometheus", "prometheus",
@@ -2125,6 +2124,7 @@ dependencies = [
"tokio-util", "tokio-util",
"tracing", "tracing",
"tracing-actix-web", "tracing-actix-web",
"tracing-log",
"tracing-opentelemetry", "tracing-opentelemetry",
"tracing-subscriber", "tracing-subscriber",
"tzf-rs", "tzf-rs",
@@ -2759,13 +2759,17 @@ dependencies = [
] ]
[[package]] [[package]]
name = "opentelemetry-appender-log" name = "opentelemetry-appender-tracing"
version = "0.31.0" version = "0.31.1"
source = "registry+https://github.com/rust-lang/crates.io-index" source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9e50c59a96bd6a723a4329c5db31eb04fa4488c5f141ae7b9d4fd587439e6ee1" checksum = "ef6a1ac5ca3accf562b8c306fa8483c85f4390f768185ab775f242f7fe8fdcc2"
dependencies = [ dependencies = [
"log",
"opentelemetry", "opentelemetry",
"tracing",
"tracing-core",
"tracing-log",
"tracing-opentelemetry",
"tracing-subscriber",
] ]
[[package]] [[package]]
@@ -2813,17 +2817,6 @@ dependencies = [
"tonic-prost", "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]] [[package]]
name = "opentelemetry_sdk" name = "opentelemetry_sdk"
version = "0.31.0" version = "0.31.0"
@@ -4443,6 +4436,7 @@ dependencies = [
"thread_local", "thread_local",
"tracing", "tracing",
"tracing-core", "tracing-core",
"tracing-log",
] ]
[[package]] [[package]]
+8 -6
View File
@@ -39,11 +39,11 @@ rayon = "1.5"
path-absolutize = "3.1" path-absolutize = "3.1"
log = "0.4" log = "0.4"
env_logger = "0.11.5" env_logger = "0.11.5"
# default-features = false keeps the `tracing-log` bridge OFF so the console # `tracing-log` is ON: `try_init` installs the LogTracer bridge, so `log::`
# fmt layer prints tracing spans only; `log` records stay on their existing # records become tracing events and share the one console format + OTel
# path (env_logger in debug, OTel logs in release) without double-printing. # log export (#147 spike).
tracing = "0.1" 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-opentelemetry = "0.32"
tracing-actix-web = { version = "0.7", features = ["opentelemetry_0_31"] } tracing-actix-web = { version = "0.7", features = ["opentelemetry_0_31"] }
actix-web-prom = "0.9.0" actix-web-prom = "0.9.0"
@@ -54,8 +54,6 @@ rand = "0.8.5"
opentelemetry = { version = "0.31.0", features = ["default", "metrics", "tracing"] } opentelemetry = { version = "0.31.0", features = ["default", "metrics", "tracing"] }
opentelemetry_sdk = { version = "0.31.0", features = ["default", "rt-tokio-current-thread", "metrics", "testing"] } 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-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" tempfile = "3.20.0"
regex = "1.11.1" regex = "1.11.1"
exif = { package = "kamadak-exif", version = "0.6.1" } exif = { package = "kamadak-exif", version = "0.6.1" }
@@ -76,8 +74,12 @@ indicatif = "0.17"
uuid = { version = "1.10", features = ["v4", "serde"] } uuid = { version = "1.10", features = ["v4", "serde"] }
chrono-tz = "0.10" chrono-tz = "0.10"
tzf-rs = "2.1.2" 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. # Windows lacks system sqlite3, so re-enable the bundled C build there.
# Linux/macOS use the system library (faster builds, smaller binary). # Linux/macOS use the system library (faster builds, smaller binary).
[target.'cfg(windows)'.dependencies] [target.'cfg(windows)'.dependencies]
libsqlite3-sys = { version = "0.35", features = ["bundled"] } libsqlite3-sys = { version = "0.35", features = ["bundled"] }
[dev-dependencies]
tracing-log = "0.2"
+2 -2
View File
@@ -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) - `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 - `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 - `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` - `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 export, in any build [default: unset, no export] - `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 - `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`] - `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] - `WATCH_QUICK_INTERVAL_SECONDS` (optional) is the interval in seconds for quick file scans [default: 60]
+3 -11
View File
@@ -111,17 +111,9 @@ fn main() -> std::io::Result<()> {
let system = actix::System::new(); let system = actix::System::new();
system.block_on(async { system.block_on(async {
// One `tracing` subscriber in every build: env-driven, so dev prints // One `tracing` subscriber in every build: env-driven, so dev prints
// spans to the console and release exports them over OTLP. The `log` // spans + logs to the console and OTLP_OTLS_ENDPOINT exports both.
// pipeline stays separate — env_logger in debug, OTel logs in release. // `log::` records are bridged into it.
otel::init_tracing(); let _logger_provider = otel::init_tracing();
#[cfg(debug_assertions)]
{
env_logger::init();
}
#[cfg(not(debug_assertions))]
{
otel::init_logs();
}
// AppState construction loads (and seeds if needed) the libraries // AppState construction loads (and seeds if needed) the libraries
// table; we use that list to drive the initial thumbnail sweep. // table; we use that list to drive the initial thumbnail sweep.
+61 -48
View File
@@ -1,29 +1,33 @@
use opentelemetry::propagation::TextMapPropagator; use opentelemetry::propagation::TextMapPropagator;
use opentelemetry::trace::{Status, TraceContextExt, TracerProvider}; use opentelemetry::trace::{Status, TraceContextExt, TracerProvider};
use opentelemetry::{Context, KeyValue, global}; use opentelemetry::{Context, KeyValue, global};
use opentelemetry_appender_log::OpenTelemetryLogBridge; use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
use opentelemetry_otlp::WithExportConfig; use opentelemetry_otlp::WithExportConfig;
use opentelemetry_sdk::Resource; use opentelemetry_sdk::Resource;
use opentelemetry_sdk::logs::{BatchLogProcessor, SdkLoggerProvider}; use opentelemetry_sdk::logs::SdkLoggerProvider;
use opentelemetry_sdk::propagation::TraceContextPropagator; use opentelemetry_sdk::propagation::TraceContextPropagator;
use tracing_subscriber::Layer;
use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt; 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 /// One subscriber handles everything, in every build; behaviour comes from
/// in dev). Behaviour is driven by the environment, not the build profile: /// the environment, not the build profile:
/// - `OTLP_OTLS_ENDPOINT` set -> spans are batch-exported over OTLP (the /// - `OTLP_OTLS_ENDPOINT` set -> spans AND log records are batch-exported
/// release / staging path). /// over OTLP. Log records carry the trace_id / span_id of the span they
/// - unset -> spans are created with valid contexts (so /// were emitted in, so SigNoz correlates logs with traces.
/// outgoing `traceparent` injection still works) but exported nowhere; the /// - unset -> spans get valid contexts (outgoing
/// console `fmt` layer is what shows them. /// `traceparent` injection still works) but nothing is exported.
/// ///
/// The console `fmt` layer is always present, so a release build run locally /// The console `fmt` layer is always present. `log::` records are bridged
/// also prints spans to stdout. `log` records are NOT routed through this /// into `tracing` (the `tracing-log` feature makes `try_init` install
/// subscriber (the `tracing-log` bridge is off) — they keep their existing /// `LogTracer`), so they print in the same format and export the same way.
/// path: `env_logger` in debug, OTel logs in release. ///
pub fn init_tracing() { /// 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 // W3C propagator for the whole process: the request middleware
// (tracing-actix-web) and the outgoing `traceparent` helpers both read // (tracing-actix-web) and the outgoing `traceparent` helpers both read
// the *global* propagator, so it must be set before any request lands. // the *global* propagator, so it must be set before any request lands.
@@ -36,10 +40,11 @@ pub fn init_tracing() {
]) ])
.build(); .build();
let mut provider_builder = let endpoint = std::env::var("OTLP_OTLS_ENDPOINT").ok();
opentelemetry_sdk::trace::SdkTracerProvider::builder().with_resource(resources);
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() let span_exporter = opentelemetry_otlp::SpanExporter::builder()
.with_tonic() .with_tonic()
.with_endpoint(endpoint) .with_endpoint(endpoint)
@@ -55,7 +60,27 @@ pub fn init_tracing() {
let tracer = tracer_provider.tracer("image-server"); let tracer = tracer_provider.tracer("image-server");
global::set_tracer_provider(tracer_provider); 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 // spans exist for export. All spans are `info`, so keep it at info/debug
// (see CLAUDE.md "Tracing"); `warn` turns span export off. // (see CLAUDE.md "Tracing"); `warn` turns span export off.
tracing_subscriber::registry() tracing_subscriber::registry()
@@ -63,39 +88,27 @@ pub fn init_tracing() {
tracing_subscriber::EnvFilter::try_from_default_env() tracing_subscriber::EnvFilter::try_from_default_env()
.unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")), .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")),
) )
.with(tracing_opentelemetry::OpenTelemetryLayer::new(tracer)) .with(
.with(tracing_subscriber::fmt::layer().with_target(false)) tracing_opentelemetry::OpenTelemetryLayer::new(tracer).with_filter(span_layer_filter()),
)
.with(log_layer)
.with(tracing_subscriber::fmt::layer())
.try_init() .try_init()
.expect("failed to install tracing subscriber"); .expect("failed to install tracing subscriber");
logger_provider
} }
#[allow(dead_code)] /// Per-layer filter for the OTel span layer: every span, but only WARN and
pub fn init_logs() { /// ERROR events. `tracing-opentelemetry` copies each event it sees onto its
let otlp_exporter = opentelemetry_otlp::LogExporter::builder() /// span as a span event; with logs exported and correlated separately, the
.with_tonic() /// info/debug copies are duplicate noise in the trace view. WARN/ERROR stay
.with_endpoint(std::env::var("OTLP_OTLS_ENDPOINT").unwrap()) /// because error events set the span's status.
.build() pub fn span_layer_filter()
.unwrap(); -> tracing_subscriber::filter::FilterFn<impl Fn(&tracing::Metadata<'_>) -> bool> {
tracing_subscriber::filter::filter_fn(|meta| {
let exporter = opentelemetry_stdout::LogExporter::default(); meta.is_span() || *meta.level() <= tracing::Level::WARN
})
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);
} }
/// Start a client span for a single LLM call. Every provider funnels its /// Start a client span for a single LLM call. Every provider funnels its
+167
View File
@@ -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());
}