nordisk/holger

server/cli/src/tracing_log.rs

//! **`tracing`'s EVENTS into holger's `log`, its SPANS silent** (feature `paired`).
//!
//! A box of an installer-built estate links edda crates that speak `tracing`
//! (`appliance-pid1`, `wg-appliance-core`'s dataplane) while holger logs with
//! `env_logger`. With `tracing`'s `log` feature and NO subscriber, `tracing` turns
//! every event into a `log` record — which is what carries `appliance-pid1`'s lines
//! into the boot log the installer collects — but it turns every SPAN it opens into
//! one too, at the span's level: `wg-appliance-core` opens `warn_span!("wg", peer = …)`
//! around EVERY packet it seals, so each holger box logged `WARN wg; peer=…` once per
//! packet — 2 000+ lines in a 70 s install, an endless WARN flood through the log
//! door after it (MEASURED by the private-holger-ops estate-box gate, 2026-10-04:
//! `Z9-log-gate` red on server and twin). gunnar's boxes install a `tracing`
//! subscriber and never print a span.
//!
//! [`EventsIntoLog`] is that subscriber for holger: an event is handed to `log`
//! exactly as before (same level, target, file and line; its fields after the
//! message), a span is only an id — nothing is printed for it.

use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Id, Record};
use tracing::{Event, Metadata, Subscriber};

/// Where an event goes: `log::logger()` in the binary, a capture in the tests.
pub type Sink = fn(&log::Record<'_>);

/// The subscriber.
pub struct EventsIntoLog {
    sink: Sink,
    /// `true`: ask `log`'s own filter which events are wanted (the binary).
    filtered: bool,
}

fn to_log(l: &tracing::Level) -> log::Level {
    match *l {
        tracing::Level::ERROR => log::Level::Error,
        tracing::Level::WARN => log::Level::Warn,
        tracing::Level::INFO => log::Level::Info,
        tracing::Level::DEBUG => log::Level::Debug,
        tracing::Level::TRACE => log::Level::Trace,
    }
}

fn into_logger(r: &log::Record<'_>) {
    log::logger().log(r);
}

impl EventsIntoLog {
    /// Into the process's `log` logger, under its filter.
    pub fn logger() -> EventsIntoLog {
        EventsIntoLog {
            sink: into_logger,
            filtered: true,
        }
    }
    /// Into `sink`, every event.
    pub fn with(sink: Sink) -> EventsIntoLog {
        EventsIntoLog {
            sink,
            filtered: false,
        }
    }
}

/// The message, then every other field as `name=value`.
#[derive(Default)]
struct Line {
    message: String,
    fields: String,
}

impl Visit for Line {
    fn record_str(&mut self, field: &Field, value: &str) {
        if field.name() == "message" {
            self.message = value.to_string();
        } else {
            self.fields.push_str(&format!(" {}={value}", field.name()));
        }
    }
    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
        if field.name() == "message" {
            self.message = format!("{value:?}");
        } else {
            self.fields
                .push_str(&format!(" {}={value:?}", field.name()));
        }
    }
}

impl Subscriber for EventsIntoLog {
    fn enabled(&self, m: &Metadata<'_>) -> bool {
        // A span is never printed: enabling it costs nothing and keeps `in_scope` cheap.
        if m.is_span() || !self.filtered {
            return true;
        }
        let level = to_log(m.level());
        level <= log::max_level()
            && log::logger().enabled(
                &log::Metadata::builder()
                    .level(level)
                    .target(m.target())
                    .build(),
            )
    }
    fn new_span(&self, _: &Attributes<'_>) -> Id {
        Id::from_u64(1)
    }
    fn record(&self, _: &Id, _: &Record<'_>) {}
    fn record_follows_from(&self, _: &Id, _: &Id) {}
    fn event(&self, e: &Event<'_>) {
        let m = e.metadata();
        let mut line = Line::default();
        e.record(&mut line);
        (self.sink)(
            &log::Record::builder()
                .args(format_args!("{}{}", line.message, line.fields))
                .level(to_log(m.level()))
                .target(m.target())
                .module_path(m.module_path())
                .file(m.file())
                .line(m.line())
                .build(),
        );
    }
    fn enter(&self, _: &Id) {}
    fn exit(&self, _: &Id) {}
}

#[cfg(test)]
mod tests {
    use super::*;

    thread_local! {
        static SEEN: std::cell::RefCell<Vec<(log::Level, String)>> = const { std::cell::RefCell::new(Vec::new()) };
    }

    fn capture(r: &log::Record<'_>) {
        SEEN.with(|s| s.borrow_mut().push((r.level(), r.args().to_string())));
    }

    /// ★ **A span prints nothing, an event prints itself** — RED before this module:
    /// with `tracing`'s `log` feature and no subscriber, `warn_span!("wg", peer = …)`
    /// printed `WARN wg; peer=…` once per packet on every box.
    #[test]
    fn a_span_is_silent_and_an_event_keeps_its_level_message_and_fields() {
        SEEN.with(|s| s.borrow_mut().clear());
        tracing::subscriber::with_default(EventsIntoLog::with(capture), || {
            for _ in 0..100 {
                let span = tracing::warn_span!("wg", peer = "wg-installer:installer:QEYw0Mje");
                let _in = span.enter();
            }
            tracing::warn!(
                device = "LNXPWRBN",
                "the ACPI power button cannot be heard on this kernel"
            );
            tracing::info!("wg: the peer that dials this end is back");
        });
        let seen = SEEN.with(|s| s.borrow().clone());
        assert_eq!(seen.len(), 2, "{seen:?}");
        assert!(
            !seen.iter().any(|(_, l)| l.contains("wg; peer=")),
            "a span printed itself: {seen:?}"
        );
        assert_eq!(
            seen[0],
            (
                log::Level::Warn,
                "the ACPI power button cannot be heard on this kernel device=LNXPWRBN".to_string()
            )
        );
        assert_eq!(seen[1].0, log::Level::Info);
    }
}