scion_sdk_observability/
lib.rs

1// Copyright 2025 Anapaya Systems
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7//   http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14//! Observability crate for logging and prometheus metrics.
15
16use std::{
17    fmt,
18    io::{IsTerminal, Write},
19    str::FromStr,
20    sync::{Arc, Mutex},
21};
22
23use chacha20::ChaCha20Rng;
24use http::Request;
25use rand::{Rng, SeedableRng, rng};
26use tower_http::{
27    LatencyUnit,
28    classify::{ServerErrorsAsFailures, SharedClassifier},
29    trace::{DefaultOnFailure, DefaultOnResponse, MakeSpan, TraceLayer},
30};
31use tracing::Span;
32use tracing_appender::non_blocking::{NonBlocking, WorkerGuard};
33use tracing_bunyan_formatter::{BunyanFormattingLayer, JsonStorageLayer};
34use tracing_subscriber::{
35    EnvFilter, Layer, Registry,
36    field::RecordFields,
37    fmt::{
38        FormatFields,
39        format::{DefaultFields, Format, Writer},
40        time::UtcTime,
41    },
42    prelude::*,
43};
44
45use crate::{dedup::DeduplicatingFormatter, log_metrics::LogEntriesLayer};
46
47pub mod dedup;
48pub mod log_metrics;
49pub mod metrics;
50pub mod prometheus_json;
51
52pub use tracing_subscriber;
53
54/// Environment variable to define the log level.
55pub const LOG_LEVEL_ENV: &str = "RUST_LOG";
56
57/// Selects where log lines are written.
58#[derive(Debug, Clone, PartialEq, Eq, Default, serde::Serialize, serde::Deserialize)]
59#[serde(rename_all = "lowercase")]
60pub enum LogOutput {
61    /// Write to stderr.
62    #[default]
63    Stderr,
64    /// Write to stdout.
65    Stdout,
66}
67
68impl FromStr for LogOutput {
69    type Err = String;
70
71    fn from_str(s: &str) -> Result<Self, Self::Err> {
72        match s.to_lowercase().as_str() {
73            "stdout" => Ok(LogOutput::Stdout),
74            "stderr" => Ok(LogOutput::Stderr),
75            _ => {
76                Err(format!(
77                    "Invalid log output: '{}', expected 'stdout' or 'stderr'",
78                    s
79                ))
80            }
81        }
82    }
83}
84
85impl fmt::Display for LogOutput {
86    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
87        match self {
88            LogOutput::Stdout => write!(f, "stdout"),
89            LogOutput::Stderr => write!(f, "stderr"),
90        }
91    }
92}
93
94/// Selects the log line format.
95#[derive(Debug, Clone, PartialEq, Eq, Default, serde::Serialize, serde::Deserialize)]
96#[serde(rename_all = "lowercase")]
97pub enum LogFormat {
98    /// Human-readable text, with ANSI colours when the output is a terminal.
99    #[default]
100    Text,
101    /// Newline-delimited JSON.
102    Json,
103}
104
105impl FromStr for LogFormat {
106    type Err = String;
107
108    fn from_str(s: &str) -> Result<Self, Self::Err> {
109        match s.to_lowercase().as_str() {
110            "text" => Ok(LogFormat::Text),
111            "json" => Ok(LogFormat::Json),
112            _ => {
113                Err(format!(
114                    "Invalid log format: '{}', expected 'text' or 'json'",
115                    s
116                ))
117            }
118        }
119    }
120}
121
122impl fmt::Display for LogFormat {
123    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
124        match self {
125            LogFormat::Text => write!(f, "text"),
126            LogFormat::Json => write!(f, "json"),
127        }
128    }
129}
130
131/// Configuration for tracing setup.
132pub struct TracingConfig {
133    /// Console output sink. `None` disables console logging.
134    console_output: Option<LogOutput>,
135    console_format: LogFormat,
136    /// Collapse consecutive identical console events into a repeat summary.
137    console_dedup: bool,
138    /// Counts emitted log entries by level, if enabled.
139    log_entries: Option<LogEntriesLayer>,
140    directives: Vec<String>,
141    extra_layers: Vec<Box<dyn Layer<Registry> + Send + Sync + 'static>>,
142}
143
144impl Default for TracingConfig {
145    fn default() -> Self {
146        Self {
147            // Default: human-readable text → stderr (preserves existing behaviour).
148            console_output: Some(LogOutput::Stderr),
149            console_format: LogFormat::Text,
150            console_dedup: false,
151            log_entries: None,
152            directives: Vec::new(),
153            extra_layers: Vec::new(),
154        }
155    }
156}
157
158impl TracingConfig {
159    /// Create a new tracing configuration with defaults.
160    pub fn new() -> Self {
161        Self::default()
162    }
163
164    /// Set where console log lines are written.
165    /// Call with the desired [`LogOutput`] variant. To disable console logging
166    /// entirely pass `None` directly via `TracingConfig { console_output: None, .. }`
167    /// or build the config manually.
168    pub fn with_output(mut self, output: LogOutput) -> Self {
169        self.console_output = Some(output);
170        self
171    }
172
173    /// Set the console log format.
174    pub fn with_format(mut self, format: LogFormat) -> Self {
175        self.console_format = format;
176        self
177    }
178
179    /// Enable or disable deduplication of consecutive identical console events.
180    ///
181    /// When enabled, a run of identical events (same message, level and target)
182    /// is written only once, followed by a `previous message repeated N times`
183    /// summary when a different event arrives. See [`dedup::DeduplicatingFormatter`].
184    pub fn with_deduplication(mut self, enabled: bool) -> Self {
185        self.console_dedup = enabled;
186        self
187    }
188
189    /// Count emitted log entries by level, exposing the counter on `registry`. Disabled by
190    /// default.
191    ///
192    /// The counter is registered here rather than when tracing is initialized, so that it lands on
193    /// the registry the caller serves. Pass the registry that is exposed to Prometheus; a counter
194    /// registered elsewhere is counted but never scraped.
195    pub fn with_log_metrics(mut self, registry: &metrics::registry::MetricsRegistry) -> Self {
196        self.log_entries = Some(LogEntriesLayer::new(registry));
197        self
198    }
199
200    /// Add an additional tracing directive.
201    pub fn add_directive<S: Into<String>>(mut self, directive: S) -> Self {
202        self.directives.push(directive.into());
203        self
204    }
205
206    /// Add multiple tracing directives.
207    pub fn add_directives<I, S>(mut self, directives: I) -> Self
208    where
209        I: IntoIterator<Item = S>,
210        S: AsRef<str>,
211    {
212        for directive in directives {
213            self.directives.push(directive.as_ref().to_string());
214        }
215        self
216    }
217
218    /// Add a custom tracing layer.
219    pub fn with_layer<L>(mut self, layer: L) -> Self
220    where
221        L: Layer<Registry> + Send + Sync + 'static,
222    {
223        self.extra_layers.push(layer.boxed());
224        self
225    }
226
227    /// Initialize tracing using this configuration.
228    ///
229    /// The tracing directives from the configuration are applied to all layers.
230    pub fn init(self) -> Result<Vec<WorkerGuard>, TracingSetupError> {
231        // Setup log tracer to forward log records to tracing subscriber, this is required to
232        // capture logs from dependencies such as squiche.
233        tracing_log::LogTracer::init().map_err(|err| {
234            TracingSetupError {
235                message: format!("Failed to initialize log tracer: {err}"),
236            }
237        })?;
238
239        let TracingConfig {
240            console_output,
241            console_format,
242            console_dedup,
243            log_entries,
244            directives,
245            extra_layers,
246        } = self;
247
248        // Closure that builds a fresh EnvFilter with all configured directives applied.
249        // Called once per logger so that each layer gets its own independent filter
250        // (EnvFilter does not implement Clone).
251        let make_filter = |directives: &[String]| -> Result<EnvFilter, TracingSetupError> {
252            let mut filter =
253                EnvFilter::try_from_env(LOG_LEVEL_ENV).unwrap_or_else(|_| EnvFilter::new("info"));
254            for d in directives {
255                filter = filter.add_directive(
256                    d.parse::<tracing_subscriber::filter::Directive>()
257                        .map_err(|_| {
258                            TracingSetupError {
259                                message: format!("Invalid log directive: {d}"),
260                            }
261                        })?,
262                );
263            }
264            Ok(filter)
265        };
266
267        let mut guards = vec![];
268        let mut layers = vec![JsonStorageLayer.boxed()];
269
270        if let Some(output) = console_output {
271            let (writer, guard, ansi) = match output {
272                LogOutput::Stdout => {
273                    let (writer, guard) = tracing_appender::non_blocking(std::io::stdout());
274                    (writer, guard, std::io::stdout().is_terminal())
275                }
276                LogOutput::Stderr => {
277                    let (writer, guard) = tracing_appender::non_blocking(std::io::stderr());
278                    (writer, guard, std::io::stderr().is_terminal())
279                }
280            };
281            layers.push(console_layer(
282                writer,
283                &console_format,
284                ansi,
285                console_dedup,
286                make_filter(&directives)?,
287            ));
288            guards.push(guard);
289        }
290
291        if let Some(layer) = log_entries {
292            layers.push(layer.with_filter(make_filter(&directives)?).boxed());
293        }
294
295        // add any additionally configured layers
296        for layer in extra_layers {
297            layers.push(layer.with_filter(make_filter(&directives)?).boxed());
298        }
299
300        // global subscriber
301        let subscriber = Registry::default().with(layers);
302        tracing::subscriber::set_global_default(subscriber).map_err(|err| {
303            TracingSetupError {
304                message: format!("Failed to set global tracing subscriber: {err}"),
305            }
306        })?;
307
308        tracing::debug!("Logging initialized!");
309        Ok(guards)
310    }
311}
312
313/// Field formatter for the console text layer, distinct from the default so the console owns its
314/// own span-field cache slot.
315///
316/// A `tracing_subscriber` `fmt` layer formats and caches each span's fields exactly once, stored in
317/// the span's extensions keyed by the layer's field-formatter type. If the console layer used the
318/// default [`DefaultFields`], it would share the `FormattedFields<DefaultFields>` slot with any
319/// extra `fmt` layer a caller adds. Whichever layer sees a span first wins the cache, so the
320/// ANSI-colored console output would leak escape sequences into the other layer's rendering (and
321/// vice versa). Giving the console its own wrapper type isolates its (ANSI) cache from callers'
322/// default `fmt` layers, so their output is unaffected by the console's coloring regardless of
323/// layer order.
324#[derive(Default)]
325struct ConsoleFields(DefaultFields);
326
327impl<'writer> FormatFields<'writer> for ConsoleFields {
328    fn format_fields<R: RecordFields>(&self, writer: Writer<'writer>, fields: R) -> fmt::Result {
329        self.0.format_fields(writer, fields)
330    }
331}
332
333/// Build a console logging layer for the given writer, format and options (e.g. ANSI terminal
334/// colors, log deduplication).
335fn console_layer(
336    writer: NonBlocking,
337    format: &LogFormat,
338    ansi: bool,
339    dedup: bool,
340    filter: EnvFilter,
341) -> Box<dyn Layer<Registry> + Send + Sync + 'static> {
342    match format {
343        LogFormat::Json => {
344            let fmt = Format::default().json().with_timer(UtcTime::rfc_3339());
345            let layer = tracing_subscriber::fmt::layer().json().with_writer(writer);
346            if dedup {
347                let fmt = DeduplicatingFormatter::new(fmt).with_format(LogFormat::Json);
348                layer.event_format(fmt).with_filter(filter).boxed()
349            } else {
350                layer.event_format(fmt).with_filter(filter).boxed()
351            }
352        }
353        LogFormat::Text => {
354            let fmt = Format::default()
355                .with_timer(UtcTime::rfc_3339())
356                .with_ansi(ansi);
357            let layer = tracing_subscriber::fmt::layer()
358                .fmt_fields(ConsoleFields::default())
359                .with_writer(writer);
360            if dedup {
361                layer
362                    .event_format(DeduplicatingFormatter::new(fmt))
363                    .with_filter(filter)
364                    .boxed()
365            } else {
366                layer.event_format(fmt).with_filter(filter).boxed()
367            }
368        }
369    }
370}
371
372/// Error returned when tracing setup fails.
373#[derive(Debug)]
374pub struct TracingSetupError {
375    message: String,
376}
377
378impl fmt::Display for TracingSetupError {
379    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
380        write!(f, "{}", self.message)
381    }
382}
383
384impl std::error::Error for TracingSetupError {}
385
386#[allow(unused)]
387fn json_formatted_layer<W: Write + Send + 'static>(
388    w: W,
389) -> (BunyanFormattingLayer<NonBlocking>, WorkerGuard) {
390    let app_name = env!("CARGO_PKG_NAME").to_string();
391    let (non_blocking_writer, guard) = tracing_appender::non_blocking(w);
392    (
393        BunyanFormattingLayer::new(app_name, non_blocking_writer),
394        guard,
395    )
396}
397
398/// Trace layer that logs at info level and uses random span ids.
399pub fn info_trace_layer() -> TraceLayer<SharedClassifier<ServerErrorsAsFailures>, RandomSpans> {
400    let lvl = tracing::Level::INFO;
401    let trace_id_seed = rng().next_u64();
402    let latency_unit = LatencyUnit::Nanos;
403
404    TraceLayer::new_for_http()
405        .make_span_with(RandomSpans::new(trace_id_seed))
406        .on_failure(
407            DefaultOnFailure::new()
408                .latency_unit(latency_unit)
409                .level(lvl),
410        )
411        .on_response(
412            DefaultOnResponse::new()
413                .latency_unit(latency_unit)
414                .level(lvl),
415        )
416}
417
418/// Random span generator.
419#[derive(Clone)]
420pub struct RandomSpans {
421    counter: Arc<Mutex<ChaCha20Rng>>,
422}
423
424impl RandomSpans {
425    fn new(seed: u64) -> Self {
426        Self {
427            counter: Arc::new(Mutex::new(ChaCha20Rng::seed_from_u64(seed))),
428        }
429    }
430}
431
432impl<B> MakeSpan<B> for RandomSpans {
433    fn make_span(&mut self, request: &Request<B>) -> Span {
434        let cur = self.counter.lock().unwrap().next_u64();
435        let span_id = format!("{cur:016x}");
436        tracing::span!(
437            tracing::Level::INFO,
438            "request",
439            span_id = span_id,
440            method = %request.method(),
441            uri = %request.uri(),
442            version = ?request.version(),
443        )
444    }
445}
446
447#[cfg(test)]
448mod tests {
449    use std::sync::{Arc, Mutex};
450
451    use tracing_subscriber::{EnvFilter, Layer, Registry, prelude::*};
452
453    use super::{LogFormat, console_layer};
454
455    /// A `MakeWriter` writer that captures everything written into a shared buffer.
456    #[derive(Clone)]
457    struct BufWriter(Arc<Mutex<Vec<u8>>>);
458
459    impl std::io::Write for BufWriter {
460        fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
461            self.0.lock().unwrap().extend_from_slice(buf);
462            Ok(buf.len())
463        }
464
465        fn flush(&mut self) -> std::io::Result<()> {
466            Ok(())
467        }
468    }
469
470    /// Regression test: an ANSI-enabled console text layer must not leak color codes into an extra
471    /// `fmt` layer added by a caller.
472    ///
473    /// This reproduces the production wiring in [`TracingConfig::init`]: the console layer is
474    /// registered before the caller's extra layer, so it wins the per-span field-formatting cache.
475    /// Before the console layer used its own field-formatter type, the cached ANSI-colored span
476    /// fields bled into the extra layer's rendering (the extra layer disables ANSI, but that only
477    /// governs the text it renders itself, not the shared span-field cache).
478    #[test]
479    fn console_ansi_does_not_leak_into_extra_fmt_layer() {
480        let captured = Arc::new(Mutex::new(Vec::new()));
481
482        // The real console text layer with ANSI enabled, as built by `TracingConfig`.
483        let (console_writer, _guard) = tracing_appender::non_blocking(std::io::sink());
484        let console = console_layer(
485            console_writer,
486            &LogFormat::Text,
487            /* ansi */ true,
488            /* dedup */ false,
489            EnvFilter::new("info"),
490        );
491
492        // A caller-supplied extra `fmt` layer that disables ANSI (e.g. one forwarding logs to a UI
493        // or file) using the default field formatter.
494        let extra = {
495            let captured = captured.clone();
496            tracing_subscriber::fmt::layer()
497                .with_ansi(false)
498                .with_writer(move || BufWriter(captured.clone()))
499                .boxed()
500        };
501
502        // Mirror production ordering: console first, then the extra layer.
503        let layers: Vec<Box<dyn Layer<Registry> + Send + Sync>> = vec![console, extra];
504        let subscriber = Registry::default().with(layers);
505
506        tracing::subscriber::with_default(subscriber, || {
507            let span = tracing::info_span!("meta-comment", test = "test-field");
508            let _guard = span.enter();
509            tracing::info!("test log");
510        });
511
512        let out = String::from_utf8(captured.lock().unwrap().clone()).expect("valid utf-8");
513        assert!(
514            !out.contains('\u{1b}'),
515            "extra layer must not inherit ANSI escapes from the console layer, got: {out:?}"
516        );
517        // Sanity check that span context is still rendered in the extra layer.
518        assert!(
519            out.contains("meta-comment") && out.contains("test-field"),
520            "extra layer should still render span name and fields, got: {out:?}"
521        );
522    }
523}
scion_sdk_observability/lib.rs

scion_sdk_observability/
lib.rs
