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}