Skip to main content

dynomite/core/log/
mod.rs

1//! Leveled logger built on `tracing` + `tracing-subscriber`.
2//!
3//! The `-v` command-line flag selects an integer log level
4//! (`LOG_EMERG = 0` ... `LOG_PVERB = 11`). Callers pass the
5//! numeric 0..11 verbosity and [`tracing_level_for`] maps it onto
6//! the underlying `tracing` level filter.
7//!
8//! On startup, [`log_init`] installs a global [`tracing_subscriber`]
9//! that writes to either standard error or to a configurable log file.
10//! Sending `SIGHUP` reopens the log file at the stored path; the helper
11//! [`reopen_on_sighup`] is what the signal handler invokes.
12//!
13//! Four output shapes are supported, dispatched by [`LogFormat`]:
14//! [`LogFormat::Default`] (the historical text format), [`LogFormat::Rfc5424`]
15//! (modern syslog), [`LogFormat::Rfc3164`] (BSD syslog), and
16//! [`LogFormat::Json`] (NDJSON). Operators select a shape via the
17//! `log_format:` configuration key or the `--log-format` CLI flag;
18//! when neither is set the default value reproduces the pre-existing
19//! behavior byte-for-byte.
20//!
21//! # Examples
22//!
23//! ```
24//! use dynomite::core::log::{log_init, tracing_level_for, LOG_NOTICE};
25//! use tracing::Level;
26//!
27//! assert_eq!(tracing_level_for(LOG_NOTICE), Level::INFO);
28//! // `log_init` is process-global; this is illustrative only.
29//! let _ = log_init(LOG_NOTICE, None);
30//! ```
31
32use std::fs::{File, OpenOptions};
33use std::io::{self, Write};
34use std::path::{Path, PathBuf};
35use std::sync::atomic::{AtomicU8, Ordering};
36use std::sync::OnceLock;
37
38use parking_lot::Mutex;
39use tracing::Level;
40use tracing_subscriber::filter::LevelFilter;
41use tracing_subscriber::fmt::MakeWriter;
42use tracing_subscriber::layer::SubscriberExt as _;
43use tracing_subscriber::registry::LookupSpan;
44use tracing_subscriber::util::SubscriberInitExt as _;
45use tracing_subscriber::{EnvFilter, Layer, Registry};
46
47use crate::core::types::{DynError, Status};
48
49mod format;
50mod host;
51mod syslog;
52
53pub use format::{LogFormat, LogFormatParseError};
54pub use host::local_hostname;
55
56/// System is unusable.
57pub const LOG_EMERG: u8 = 0;
58/// Action must be taken immediately.
59pub const LOG_ALERT: u8 = 1;
60/// Critical conditions.
61pub const LOG_CRIT: u8 = 2;
62/// Error conditions.
63pub const LOG_ERR: u8 = 3;
64/// Warning conditions.
65pub const LOG_WARN: u8 = 4;
66/// Normal but significant condition (default).
67pub const LOG_NOTICE: u8 = 5;
68/// Informational.
69pub const LOG_INFO: u8 = 6;
70/// Debug messages.
71pub const LOG_DEBUG: u8 = 7;
72/// Verbose messages.
73pub const LOG_VERB: u8 = 8;
74/// Verbose messages, second tier.
75pub const LOG_VVERB: u8 = 9;
76/// Verbose messages, third tier.
77pub const LOG_VVVERB: u8 = 10;
78/// Periodic verbose messages.
79pub const LOG_PVERB: u8 = 11;
80
81/// Largest accepted verbosity level.
82///
83/// # Examples
84///
85/// ```
86/// use dynomite::core::log::{clamp_level, LOG_LEVEL_MAX};
87/// assert_eq!(clamp_level(LOG_LEVEL_MAX + 5), LOG_LEVEL_MAX);
88/// ```
89pub const LOG_LEVEL_MAX: u8 = LOG_PVERB;
90
91/// Map a Dynomite numeric verbosity to a `tracing::Level`.
92///
93/// Levels 0..=4 are mapped to `ERROR`, 5..=6 to `INFO`, 7 to `DEBUG`,
94/// and 8..=11 to `TRACE`. Values above [`LOG_LEVEL_MAX`] saturate to
95/// `TRACE`.
96///
97/// # Examples
98///
99/// ```
100/// use dynomite::core::log::{tracing_level_for, LOG_DEBUG, LOG_PVERB, LOG_WARN};
101/// use tracing::Level;
102///
103/// assert_eq!(tracing_level_for(LOG_WARN), Level::ERROR);
104/// assert_eq!(tracing_level_for(LOG_DEBUG), Level::DEBUG);
105/// assert_eq!(tracing_level_for(LOG_PVERB), Level::TRACE);
106/// ```
107pub fn tracing_level_for(level: u8) -> Level {
108    match level {
109        0..=4 => Level::ERROR,
110        5..=6 => Level::INFO,
111        7 => Level::DEBUG,
112        _ => Level::TRACE,
113    }
114}
115
116/// Clamp the supplied verbosity to the inclusive `[0, LOG_LEVEL_MAX]`
117/// window.
118///
119/// # Examples
120///
121/// ```
122/// use dynomite::core::log::{clamp_level, LOG_LEVEL_MAX};
123/// assert_eq!(clamp_level(3), 3);
124/// assert_eq!(clamp_level(255), LOG_LEVEL_MAX);
125/// ```
126pub fn clamp_level(level: u8) -> u8 {
127    level.min(LOG_LEVEL_MAX)
128}
129
130struct State {
131    path: Mutex<Option<PathBuf>>,
132    sink: Mutex<Box<dyn Write + Send>>,
133    nerror: Mutex<u64>,
134}
135
136static STATE: OnceLock<State> = OnceLock::new();
137static CURRENT_LEVEL: AtomicU8 = AtomicU8::new(LOG_NOTICE);
138
139#[derive(Clone)]
140struct LoggerWriter;
141
142impl Write for LoggerWriter {
143    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
144        let Some(state) = STATE.get() else {
145            return io::stderr().write(buf);
146        };
147        let mut sink = state.sink.lock();
148        match sink.write_all(buf) {
149            Ok(()) => Ok(buf.len()),
150            Err(err) => {
151                *state.nerror.lock() += 1;
152                Err(err)
153            }
154        }
155    }
156
157    fn flush(&mut self) -> io::Result<()> {
158        let Some(state) = STATE.get() else {
159            return io::stderr().flush();
160        };
161        let mut sink = state.sink.lock();
162        sink.flush()
163    }
164}
165
166impl<'a> MakeWriter<'a> for LoggerWriter {
167    type Writer = LoggerWriter;
168    fn make_writer(&'a self) -> Self::Writer {
169        LoggerWriter
170    }
171}
172
173fn open_log_file(path: &Path) -> io::Result<File> {
174    OpenOptions::new()
175        .append(true)
176        .create(true)
177        .mode_for_append()
178        .open(path)
179}
180
181trait OpenOptionsExt {
182    fn mode_for_append(&mut self) -> &mut Self;
183}
184
185impl OpenOptionsExt for OpenOptions {
186    #[cfg(unix)]
187    fn mode_for_append(&mut self) -> &mut Self {
188        use std::os::unix::fs::OpenOptionsExt as _;
189        self.mode(0o644)
190    }
191    #[cfg(not(unix))]
192    fn mode_for_append(&mut self) -> &mut Self {
193        self
194    }
195}
196
197/// Bundle of tunables consumed by [`build_logs_layer`] and
198/// [`install_logs_only`].
199///
200/// Mirrors the legacy positional triple `(level, path, format)`
201/// that [`log_init_with_format`] takes; lifting it to a struct
202/// lets the binary share a single value between the OTLP-on and
203/// OTLP-off install paths.
204///
205/// # Examples
206///
207/// ```
208/// use dynomite::core::log::{LogConfig, LogFormat, LOG_NOTICE};
209/// let cfg = LogConfig::new(LOG_NOTICE, None, LogFormat::Json);
210/// assert_eq!(cfg.verbosity, LOG_NOTICE);
211/// assert_eq!(cfg.format, LogFormat::Json);
212/// ```
213#[derive(Debug, Clone)]
214pub struct LogConfig {
215    /// Numeric verbosity (`0..=LOG_LEVEL_MAX`).
216    pub verbosity: u8,
217    /// Optional log file. When `None`, log records flow to standard
218    /// error.
219    pub output: Option<PathBuf>,
220    /// Wire shape for emitted records.
221    pub format: LogFormat,
222}
223
224impl LogConfig {
225    /// Convenience constructor.
226    ///
227    /// # Examples
228    ///
229    /// ```
230    /// use dynomite::core::log::{LogConfig, LogFormat, LOG_INFO};
231    /// let cfg = LogConfig::new(LOG_INFO, None, LogFormat::Default);
232    /// assert_eq!(cfg.verbosity, LOG_INFO);
233    /// ```
234    pub fn new(verbosity: u8, output: Option<PathBuf>, format: LogFormat) -> Self {
235        Self {
236            verbosity,
237            output,
238            format,
239        }
240    }
241}
242
243/// Boxed fmt layer returned by [`build_logs_layer`].
244///
245/// The layer is parameterised on [`tracing_subscriber::Registry`]
246/// so callers can drop it into any registry stack the binary
247/// builds (with or without an [`tracing_opentelemetry`] layer
248/// stacked on top).
249pub type LogsLayer = Box<dyn Layer<Registry> + Send + Sync + 'static>;
250
251/// Token returned by [`build_logs_layer`] proving the SIGHUP
252/// log-reopen state has been initialised.
253///
254/// The token is zero-sized; its sole purpose is to make the
255/// "build the fmt layer, then install it as a global" handshake
256/// type-checked: callers cannot call [`reopen_on_sighup`] before
257/// the writer state has been wired, because they cannot construct
258/// a [`ReopenHandle`] without first calling [`build_logs_layer`]
259/// or one of its convenience wrappers.
260///
261/// # Examples
262///
263/// ```
264/// use dynomite::core::log::{build_logs_layer, LogConfig, LogFormat, LOG_NOTICE};
265/// // Building the layer also populates the SIGHUP-reopen state.
266/// // The handle below is the proof of that wiring.
267/// // (The example does not install the layer as a global so it
268/// // can run side-by-side with the rest of the doctest suite.)
269/// let cfg = LogConfig::new(LOG_NOTICE, None, LogFormat::Default);
270/// let _ = build_logs_layer(&cfg);
271/// ```
272#[derive(Debug)]
273#[must_use = "the reopen handle must be threaded into install_global so SIGHUP-reopen is wired"]
274pub struct ReopenHandle {
275    _private: (),
276}
277
278/// Build the EnvFilter the install paths feed into the registry.
279///
280/// Honours `RUST_LOG` and falls back to the `tracing` level
281/// derived from the supplied `verbosity`.
282///
283/// # Examples
284///
285/// ```
286/// use dynomite::core::log::{build_env_filter, LOG_NOTICE};
287/// let _filter = build_env_filter(LOG_NOTICE);
288/// ```
289pub fn build_env_filter(verbosity: u8) -> EnvFilter {
290    let level_filter = LevelFilter::from_level(tracing_level_for(clamp_level(verbosity)));
291    EnvFilter::builder()
292        .with_default_directive(level_filter.into())
293        .from_env_lossy()
294}
295
296fn init_reopen_state(verbosity: u8, path: Option<&Path>) -> Result<ReopenHandle, DynError> {
297    let sink: Box<dyn Write + Send> = match path {
298        Some(p) => Box::new(open_log_file(p).map_err(DynError::Io)?),
299        None => Box::new(io::stderr()),
300    };
301    let stored_path = path.map(PathBuf::from);
302
303    let state = State {
304        path: Mutex::new(stored_path),
305        sink: Mutex::new(sink),
306        nerror: Mutex::new(0),
307    };
308    STATE
309        .set(state)
310        .map_err(|_| DynError::generic("log: writer state already installed"))?;
311    CURRENT_LEVEL.store(clamp_level(verbosity), Ordering::Relaxed);
312    Ok(ReopenHandle { _private: () })
313}
314
315/// Build the fmt layer for the configured shape and wire the
316/// SIGHUP-reopen writer state.
317///
318/// Returns the boxed layer plus a [`ReopenHandle`] proving the
319/// internal writer state has been populated. The layer is *not*
320/// installed as a global; the caller composes it into a
321/// [`tracing_subscriber::Registry`] (typically together with an
322/// [`EnvFilter`] and an optional `OpenTelemetryLayer`) and calls
323/// `try_init`.
324///
325/// May only be called once per process: the underlying writer
326/// state is a `OnceLock` and a second call returns
327/// [`DynError::Generic`].
328///
329/// # Errors
330/// Returns [`DynError::Io`] when the configured `output` cannot
331/// be opened for append, and [`DynError::Generic`] when the
332/// writer state has already been initialised.
333///
334/// # Examples
335///
336/// ```no_run
337/// use dynomite::core::log::{build_env_filter, build_logs_layer, LogConfig, LogFormat, LOG_NOTICE};
338/// use tracing_subscriber::layer::SubscriberExt as _;
339/// use tracing_subscriber::util::SubscriberInitExt as _;
340///
341/// let cfg = LogConfig::new(LOG_NOTICE, None, LogFormat::Default);
342/// let (layer, _reopen) = build_logs_layer(&cfg).expect("build layer");
343/// tracing_subscriber::registry()
344///     .with(layer)
345///     .with(build_env_filter(LOG_NOTICE))
346///     .try_init()
347///     .expect("install");
348/// ```
349pub fn build_logs_layer(cfg: &LogConfig) -> Result<(LogsLayer, ReopenHandle), DynError> {
350    let reopen = init_reopen_state(cfg.verbosity, cfg.output.as_deref())?;
351    let layer = fmt_layer_for_format::<Registry>(cfg.format);
352    Ok((layer, reopen))
353}
354
355fn fmt_layer_for_format<S>(format: LogFormat) -> Box<dyn Layer<S> + Send + Sync + 'static>
356where
357    S: tracing::Subscriber + for<'lookup> LookupSpan<'lookup>,
358{
359    match format {
360        LogFormat::Default => Box::new(
361            tracing_subscriber::fmt::Layer::default()
362                .with_writer(LoggerWriter)
363                .with_target(true),
364        ),
365        LogFormat::Json => Box::new(
366            tracing_subscriber::fmt::Layer::default()
367                .with_writer(LoggerWriter)
368                .with_target(true)
369                .json()
370                .flatten_event(false)
371                .with_current_span(true)
372                .with_span_list(false),
373        ),
374        LogFormat::Rfc5424 => Box::new(
375            tracing_subscriber::fmt::Layer::default()
376                .with_writer(LoggerWriter)
377                .event_format(syslog::Rfc5424Formatter::new())
378                .with_ansi(false),
379        ),
380        LogFormat::Rfc3164 => Box::new(
381            tracing_subscriber::fmt::Layer::default()
382                .with_writer(LoggerWriter)
383                .event_format(syslog::Rfc3164Formatter::new())
384                .with_ansi(false),
385        ),
386    }
387}
388
389/// Install a fmt-only global tracing subscriber.
390///
391/// Composes a [`Registry`] with the EnvFilter built from
392/// `cfg.verbosity` and the fmt layer built from `cfg.format`,
393/// then sets it as the global default. The SIGHUP-reopen writer
394/// state is wired as a side effect.
395///
396/// This is the OTLP-off install path; the OTLP-on install path
397/// lives in the `dynomited` binary's `observability::install_global`
398/// and stacks an `OpenTelemetryLayer` on top of the same fmt layer.
399///
400/// May only be called once per process.
401///
402/// # Errors
403/// Returns [`DynError::Io`] when `cfg.output` cannot be opened
404/// for append, and [`DynError::Generic`] when a global tracing
405/// subscriber has already been installed.
406///
407/// # Examples
408///
409/// ```no_run
410/// use dynomite::core::log::{install_logs_only, LogConfig, LogFormat, LOG_NOTICE};
411/// install_logs_only(&LogConfig::new(LOG_NOTICE, None, LogFormat::Default))
412///     .expect("install logger");
413/// ```
414pub fn install_logs_only(cfg: &LogConfig) -> Status {
415    let env = build_env_filter(cfg.verbosity);
416    let (fmt_layer, _reopen) = build_logs_layer(cfg)?;
417    tracing_subscriber::registry()
418        .with(fmt_layer)
419        .with(env)
420        .try_init()
421        .map_err(|e| DynError::generic(format!("install_logs_only: {e}")))?;
422    Ok(())
423}
424
425/// Install the global tracing subscriber.
426///
427/// `level` is the C-style numeric verbosity in `0..=LOG_LEVEL_MAX`.
428/// Values above the maximum saturate. When `path` is `Some`, log
429/// records are appended to that file (created if missing); when `None`,
430/// records are written to standard error.
431///
432/// This entry point preserves the historical default output shape
433/// ([`LogFormat::Default`]). To pick a different shape, call
434/// [`log_init_with_format`] directly. Both wrappers delegate to
435/// [`install_logs_only`].
436///
437/// `log_init` may be called only once per process; subsequent calls
438/// return [`DynError::Generic`].
439///
440/// # Examples
441///
442/// ```no_run
443/// use dynomite::core::log::{log_init, LOG_NOTICE};
444/// log_init(LOG_NOTICE, None).expect("install logger");
445/// ```
446pub fn log_init(level: u8, path: Option<&Path>) -> Status {
447    log_init_with_format(level, path, LogFormat::Default)
448}
449
450/// Install the global tracing subscriber with a chosen output shape.
451///
452/// See [`LogFormat`] for the supported values. The default value
453/// (`LogFormat::Default`) is byte-identical to what [`log_init`]
454/// installs, so passing it here is equivalent to the original
455/// two-argument call.
456///
457/// # Examples
458///
459/// ```no_run
460/// use dynomite::core::log::{log_init_with_format, LogFormat, LOG_NOTICE};
461/// log_init_with_format(LOG_NOTICE, None, LogFormat::Json).expect("install logger");
462/// ```
463pub fn log_init_with_format(level: u8, path: Option<&Path>, format: LogFormat) -> Status {
464    install_logs_only(&LogConfig {
465        verbosity: level,
466        output: path.map(PathBuf::from),
467        format,
468    })
469}
470
471/// Reopen the log file at the path remembered by [`log_init`].
472///
473/// Intended to be invoked from the SIGHUP handler. When the active sink
474/// is standard error (no path was set), this is a no-op and returns
475/// [`Ok`]. When the file cannot be reopened, the previous sink is left
476/// in place and the error is returned.
477///
478/// # Examples
479///
480/// ```no_run
481/// use dynomite::core::log::reopen_on_sighup;
482/// reopen_on_sighup().expect("reopen log");
483/// ```
484pub fn reopen_on_sighup() -> Status {
485    let state = STATE
486        .get()
487        .ok_or_else(|| DynError::generic("reopen_on_sighup: log not initialised"))?;
488    let path_guard = state.path.lock();
489    let Some(path) = path_guard.as_ref() else {
490        return Ok(());
491    };
492    let new_file = open_log_file(path).map_err(DynError::Io)?;
493    *state.sink.lock() = Box::new(new_file);
494    Ok(())
495}
496
497/// Number of write errors observed by the underlying sink.
498///
499/// # Examples
500///
501/// ```
502/// use dynomite::core::log::write_error_count;
503/// // Before logging is initialised the count is zero.
504/// let _: u64 = write_error_count();
505/// ```
506pub fn write_error_count() -> u64 {
507    STATE.get().map_or(0, |s| *s.nerror.lock())
508}
509
510/// Return the current numeric verbosity stored by [`log_init`].
511///
512/// # Examples
513///
514/// ```
515/// use dynomite::core::log::{current_level, log_level_set, LOG_INFO};
516/// log_level_set(LOG_INFO);
517/// assert_eq!(current_level(), LOG_INFO);
518/// ```
519pub fn current_level() -> u8 {
520    CURRENT_LEVEL.load(Ordering::Relaxed)
521}
522
523/// Bump the stored verbosity by one, saturating at [`LOG_LEVEL_MAX`].
524///
525/// The actual `tracing` filter is set once at [`log_init`] time; this
526/// updates a numeric counter that downstream subsystems read to gate
527/// periodic-verbose output.
528///
529/// # Examples
530///
531/// ```
532/// use dynomite::core::log::{log_level_increment, log_level_set};
533/// log_level_set(3);
534/// assert_eq!(log_level_increment(), 4);
535/// ```
536pub fn log_level_increment() -> u8 {
537    let prev = CURRENT_LEVEL.load(Ordering::Relaxed);
538    let next = clamp_level(prev.saturating_add(1));
539    CURRENT_LEVEL.store(next, Ordering::Relaxed);
540    next
541}
542
543/// Drop the stored verbosity by one, saturating at zero.
544///
545/// # Examples
546///
547/// ```
548/// use dynomite::core::log::{log_level_decrement, log_level_set};
549/// log_level_set(0);
550/// assert_eq!(log_level_decrement(), 0);
551/// log_level_set(5);
552/// assert_eq!(log_level_decrement(), 4);
553/// ```
554pub fn log_level_decrement() -> u8 {
555    let prev = CURRENT_LEVEL.load(Ordering::Relaxed);
556    let next = prev.saturating_sub(1);
557    CURRENT_LEVEL.store(next, Ordering::Relaxed);
558    next
559}
560
561/// Set the stored verbosity directly, clamped to `[0, LOG_LEVEL_MAX]`.
562///
563/// # Examples
564///
565/// ```
566/// use dynomite::core::log::{current_level, log_level_set, LOG_LEVEL_MAX};
567/// log_level_set(255);
568/// assert_eq!(current_level(), LOG_LEVEL_MAX);
569/// ```
570pub fn log_level_set(level: u8) {
571    CURRENT_LEVEL.store(clamp_level(level), Ordering::Relaxed);
572}
573
574/// Return whether a given numeric level is loud enough to be logged.
575///
576/// A message at `level` is loggable iff `level <= current_level()`.
577///
578/// # Examples
579///
580/// ```
581/// use dynomite::core::log::{log_level_set, log_loggable};
582/// log_level_set(5);
583/// assert!(log_loggable(0));
584/// assert!(log_loggable(5));
585/// assert!(!log_loggable(6));
586/// ```
587pub fn log_loggable(level: u8) -> bool {
588    level <= current_level()
589}
590
591#[cfg(test)]
592mod tests {
593    use super::*;
594
595    #[test]
596    fn level_mapping_is_monotone_in_verbosity() {
597        // Map both directions through a monotonic integer scale to be
598        // robust against the orientation of `tracing::Level`'s `Ord`
599        // impl, which has flipped between releases.
600        let severity = |l: Level| -> u8 {
601            match l {
602                Level::ERROR => 0,
603                Level::WARN => 1,
604                Level::INFO => 2,
605                Level::DEBUG => 3,
606                Level::TRACE => 4,
607            }
608        };
609        let mut prev = severity(tracing_level_for(0));
610        for lvl in 1..=LOG_LEVEL_MAX {
611            let cur = severity(tracing_level_for(lvl));
612            assert!(cur >= prev, "level {lvl}: severity {cur} not >= {prev}");
613            prev = cur;
614        }
615    }
616
617    #[test]
618    fn clamp_saturates() {
619        assert_eq!(clamp_level(0), 0);
620        assert_eq!(clamp_level(LOG_LEVEL_MAX), LOG_LEVEL_MAX);
621        assert_eq!(clamp_level(LOG_LEVEL_MAX + 5), LOG_LEVEL_MAX);
622        assert_eq!(clamp_level(255), LOG_LEVEL_MAX);
623    }
624
625    #[test]
626    fn level_constants_match_c() {
627        assert_eq!(LOG_EMERG, 0);
628        assert_eq!(LOG_ALERT, 1);
629        assert_eq!(LOG_CRIT, 2);
630        assert_eq!(LOG_ERR, 3);
631        assert_eq!(LOG_WARN, 4);
632        assert_eq!(LOG_NOTICE, 5);
633        assert_eq!(LOG_INFO, 6);
634        assert_eq!(LOG_DEBUG, 7);
635        assert_eq!(LOG_VERB, 8);
636        assert_eq!(LOG_VVERB, 9);
637        assert_eq!(LOG_VVVERB, 10);
638        assert_eq!(LOG_PVERB, 11);
639    }
640
641    #[test]
642    fn level_increment_and_decrement_saturate() {
643        log_level_set(0);
644        assert_eq!(log_level_decrement(), 0);
645        for _ in 0..(u32::from(LOG_LEVEL_MAX) + 5) {
646            log_level_increment();
647        }
648        assert_eq!(current_level(), LOG_LEVEL_MAX);
649        log_level_set(5);
650        assert!(log_loggable(0));
651        assert!(log_loggable(5));
652        assert!(!log_loggable(6));
653    }
654
655    #[test]
656    fn fmt_layer_builds_for_every_format() {
657        // `fmt_layer_for_format` is STATE-independent: it only
658        // constructs a boxed layer wired to `LoggerWriter`. We
659        // build one per shape so each match arm is exercised
660        // without touching the process-global writer state.
661        for format in [
662            LogFormat::Default,
663            LogFormat::Json,
664            LogFormat::Rfc5424,
665            LogFormat::Rfc3164,
666        ] {
667            let _layer = fmt_layer_for_format::<Registry>(format);
668        }
669    }
670
671    #[test]
672    fn logger_writer_falls_back_to_stderr_until_state_init() {
673        // The `LoggerWriter` routes to stderr (write) and a no-op
674        // success (flush) until STATE is installed. nextest runs
675        // this in its own process where STATE is fresh; under a
676        // single-process runner the guard keeps the assertions
677        // honest after a sibling test has installed STATE.
678        let mut w = LoggerWriter;
679        if STATE.get().is_none() {
680            // Empty write reports zero bytes via the stderr fallback.
681            let n = w.write(b"").expect("stderr write");
682            assert_eq!(n, 0);
683            w.flush().expect("stderr flush");
684        } else {
685            // STATE present: the write/flush thread through the sink.
686            w.flush().expect("sink flush");
687        }
688    }
689
690    #[test]
691    fn build_logs_layer_writer_state_swaps_on_reopen() {
692        // The fmt layer returned by `build_logs_layer` writes
693        // through the shared STATE.sink. Renaming the configured
694        // file out from under the writer and then calling
695        // `reopen_on_sighup` must rebind STATE.sink to a freshly
696        // re-created file at the original path; events emitted
697        // before the rotate land in the renamed file, events
698        // emitted after the reopen land in the new file.
699        //
700        // STATE is a `OnceLock`, so this test is the only test
701        // in the module that initialises it. nextest runs each
702        // `#[test]` in its own process; when the suite is run
703        // under plain `cargo test` this test is the canonical
704        // owner of STATE.
705        use std::fs;
706
707        let dir = tempfile::tempdir().expect("tempdir");
708        let log_path = dir.path().join("dyn.log");
709        let cfg = LogConfig::new(LOG_NOTICE, Some(log_path.clone()), LogFormat::Default);
710        let (fmt_layer, _reopen) = build_logs_layer(&cfg).expect("build layer");
711
712        let env = build_env_filter(LOG_NOTICE);
713        let sub = tracing_subscriber::registry().with(fmt_layer).with(env);
714
715        tracing::subscriber::with_default(sub, || {
716            tracing::info!(target: "dynomite::test", "first-line-marker");
717            // tracing's fmt layer writes synchronously inside
718            // `on_event`; no flush needed.
719            let rotated = dir.path().join("dyn.log.1");
720            fs::rename(&log_path, &rotated).expect("rotate file");
721            reopen_on_sighup().expect("reopen");
722            tracing::info!(target: "dynomite::test", "second-line-marker");
723        });
724
725        let rotated_contents =
726            fs::read_to_string(dir.path().join("dyn.log.1")).expect("read rotated");
727        let new_contents = fs::read_to_string(&log_path).expect("read new");
728
729        assert!(
730            rotated_contents.contains("first-line-marker"),
731            "rotated file missing first marker: {rotated_contents:?}",
732        );
733        assert!(
734            !rotated_contents.contains("second-line-marker"),
735            "rotated file unexpectedly contained second marker: {rotated_contents:?}",
736        );
737        assert!(
738            new_contents.contains("second-line-marker"),
739            "new file missing second marker: {new_contents:?}",
740        );
741        assert!(
742            !new_contents.contains("first-line-marker"),
743            "new file unexpectedly contained first marker: {new_contents:?}",
744        );
745
746        // STATE is now installed (this test owns the OnceLock for
747        // this binary). Exercise the writer's STATE-present
748        // write and flush arms directly so they are covered even
749        // when a sibling guard-test sees STATE already set.
750        let mut w = LoggerWriter;
751        let n = w.write(b"direct-write\n").expect("sink write");
752        assert_eq!(n, "direct-write\n".len());
753        w.flush().expect("sink flush");
754        assert_eq!(write_error_count(), 0);
755    }
756}
757
758#[cfg(test)]
759mod format_tests {
760    //! Per-format unit tests.
761    //!
762    //! These tests cannot install the global subscriber - that
763    //! is process-wide and other tests already use it - so each
764    //! test scopes a `tracing_subscriber` to a closure via
765    //! `tracing::subscriber::with_default` and captures the bytes
766    //! the subscriber writes to a shared `Vec<u8>`. The captured
767    //! buffer is then asserted against the format's documented
768    //! shape (regex for syslog, line-per-event JSON for NDJSON,
769    //! field-name presence for the default text format).
770
771    use std::io::{self, Write};
772    use std::sync::{Arc, Mutex};
773
774    use regex::Regex;
775    use tracing_subscriber::fmt::MakeWriter;
776
777    use super::syslog::{Rfc3164Formatter, Rfc5424Formatter};
778
779    /// Cloneable byte sink used as the writer behind a scoped
780    /// subscriber. Each `make_writer()` call hands back a
781    /// `Buffer` that pushes into the shared `Vec<u8>`.
782    #[derive(Clone, Default)]
783    struct CaptureBuffer(Arc<Mutex<Vec<u8>>>);
784
785    impl CaptureBuffer {
786        fn snapshot(&self) -> Vec<u8> {
787            self.0.lock().expect("lock CaptureBuffer").clone()
788        }
789        fn snapshot_string(&self) -> String {
790            String::from_utf8(self.snapshot()).expect("captured bytes are utf-8")
791        }
792    }
793
794    impl Write for CaptureBuffer {
795        fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
796            let mut guard = self.0.lock().expect("lock CaptureBuffer");
797            guard.extend_from_slice(buf);
798            Ok(buf.len())
799        }
800        fn flush(&mut self) -> io::Result<()> {
801            Ok(())
802        }
803    }
804
805    impl<'a> MakeWriter<'a> for CaptureBuffer {
806        type Writer = CaptureBuffer;
807        fn make_writer(&'a self) -> Self::Writer {
808            self.clone()
809        }
810    }
811
812    /// Build the four subscriber shapes against the given capture
813    /// buffer. The functions are factored out so the assertions are
814    /// next to the regex and not next to the subscriber wiring.
815    fn run_default(buf: &CaptureBuffer) {
816        // Exercise the capture buffer's no-op flush path; tracing
817        // itself writes without flushing.
818        {
819            let mut probe = buf.clone();
820            probe.flush().unwrap();
821        }
822        let sub = tracing_subscriber::fmt()
823            .with_writer(buf.clone())
824            .with_target(true)
825            .with_ansi(false)
826            .finish();
827        tracing::subscriber::with_default(sub, || {
828            tracing::info!(answer = 42, name = "ada", "hello");
829        });
830    }
831
832    fn run_rfc5424(buf: &CaptureBuffer) {
833        use tracing_subscriber::layer::SubscriberExt as _;
834        let layer = tracing_subscriber::fmt::Layer::new()
835            .with_writer(buf.clone())
836            .event_format(Rfc5424Formatter::new())
837            .with_ansi(false);
838        let sub = tracing_subscriber::registry().with(layer);
839        tracing::subscriber::with_default(sub, || {
840            tracing::info!(answer = 42, "hello");
841        });
842    }
843
844    fn run_rfc3164(buf: &CaptureBuffer) {
845        use tracing_subscriber::layer::SubscriberExt as _;
846        let layer = tracing_subscriber::fmt::Layer::new()
847            .with_writer(buf.clone())
848            .event_format(Rfc3164Formatter::new())
849            .with_ansi(false);
850        let sub = tracing_subscriber::registry().with(layer);
851        tracing::subscriber::with_default(sub, || {
852            tracing::info!(answer = 42, "hello");
853        });
854    }
855
856    fn run_json(buf: &CaptureBuffer) {
857        let sub = tracing_subscriber::fmt()
858            .with_writer(buf.clone())
859            .json()
860            .with_target(true)
861            .flatten_event(false)
862            .with_current_span(true)
863            .with_span_list(false)
864            .finish();
865        tracing::subscriber::with_default(sub, || {
866            tracing::info!(answer = 42, name = "ada", "first");
867            tracing::warn!(retry = true, "second");
868        });
869    }
870
871    #[test]
872    fn default_format_unchanged_from_baseline() {
873        let buf = CaptureBuffer::default();
874        run_default(&buf);
875        let text = buf.snapshot_string();
876        // The historical text format stamps the level, the target,
877        // the message and the field key/value pairs as
878        // `key=value`. Anything weaker would fail to detect a
879        // regression where a future refactor accidentally swaps
880        // formatters.
881        assert!(text.contains(" INFO "), "missing INFO level: {text:?}");
882        assert!(text.contains("hello"), "missing message text: {text:?}");
883        assert!(
884            text.contains("answer=42"),
885            "missing kv 'answer=42': {text:?}"
886        );
887        assert!(text.contains("name=\"ada\""), "missing kv 'name': {text:?}");
888        // Sanity: line ends with a trailing newline.
889        assert!(text.ends_with('\n'), "missing trailing newline");
890    }
891
892    #[test]
893    fn rfc5424_format_starts_with_pri_version() {
894        let buf = CaptureBuffer::default();
895        run_rfc5424(&buf);
896        let text = buf.snapshot_string();
897        // The brief specifies the regex
898        // `^<\d+>1 [\d-]+T[\d:.+-]+ \S+ dynomited \d+ - `
899        let re =
900            Regex::new(r"^<\d+>1 [\d-]+T[\d:.+\-]+ \S+ dynomited \d+ - ").expect("compile regex");
901        let first_line = text.lines().next().expect("at least one line");
902        assert!(
903            re.is_match(first_line),
904            "RFC 5424 line did not match regex: {first_line:?}"
905        );
906        assert!(
907            first_line.contains("origin@32473"),
908            "missing structured-data ID: {first_line:?}"
909        );
910        assert!(
911            first_line.contains("hello"),
912            "missing message: {first_line:?}"
913        );
914    }
915
916    #[test]
917    fn rfc3164_format_starts_with_pri_then_timestamp() {
918        let buf = CaptureBuffer::default();
919        run_rfc3164(&buf);
920        let text = buf.snapshot_string();
921        // The brief specifies the regex
922        // `^<\d+>[A-Z][a-z]{2} [\d ]\d \d{2}:\d{2}:\d{2} \S+ \S+: `
923        let re = Regex::new(r"^<\d+>[A-Z][a-z]{2} [\d ]\d \d{2}:\d{2}:\d{2} \S+ \S+: ")
924            .expect("compile regex");
925        let first_line = text.lines().next().expect("at least one line");
926        assert!(
927            re.is_match(first_line),
928            "RFC 3164 line did not match regex: {first_line:?}"
929        );
930        assert!(
931            first_line.contains("hello"),
932            "missing message: {first_line:?}"
933        );
934    }
935
936    #[test]
937    fn ndjson_format_is_one_json_per_line() {
938        let buf = CaptureBuffer::default();
939        run_json(&buf);
940        let text = buf.snapshot_string();
941        let lines: Vec<_> = text.lines().filter(|l| !l.is_empty()).collect();
942        assert!(
943            lines.len() >= 2,
944            "expected at least two JSON lines: {text:?}"
945        );
946        for line in &lines {
947            // Each line must be a self-contained JSON object.
948            let v: serde_json::Value = serde_json::from_str(line)
949                .unwrap_or_else(|e| panic!("line is not valid JSON ({e}): {line:?}"));
950            // Required keys, per the brief: timestamp, level,
951            // target, fields. The `tracing-subscriber` JSON
952            // formatter always emits `timestamp`, `level`,
953            // `target`, and a `fields` object.
954            for key in ["timestamp", "level", "target", "fields"] {
955                assert!(
956                    v.get(key).is_some(),
957                    "JSON line missing key {key:?}: {line}"
958                );
959            }
960            // Inner-newline check: a valid NDJSON line must not
961            // contain a literal '\n' character.
962            assert!(!line.contains('\n'));
963        }
964    }
965}