gunnar-common 2.0.0

//! **The log level, changeable on a running server**.
//!
//! # What an operator could not do before this
//!
//! `RUST_LOG` at start-up was the whole of it. An operator debugging a live
//! server at 03:00 had exactly one way to see more: **restart it** — which ends
//! every in-flight transfer, clears the state they were looking at, and very
//! often makes the thing they were debugging stop happening. On an appliance it
//! is worse: there is no shell to re-export a variable in, and the process is
//! PID 1.
//!
//! So the filter lives behind a [`tracing_subscriber::reload`] handle, and two
//! signals move it:
//!
//! ```text
//!   kill -USR1 <pid>     one rung more verbose:  startup → debug → trace → startup
//!   kill -USR2 <pid>     straight back to the startup filter
//! ```
//!
//! **Signals, not a port and not an RPC.** A port is the thing this module is
//! most careful not to open, and the gRPC control plane is exactly what an
//! operator cannot reach when the control plane is what is wedged. A signal
//! needs no listener, no credential, no client binary and no runtime; it works
//! on an appliance, in a distroless container, and on a process whose gRPC
//! thread pool is starved. `SIGUSR1`/`SIGUSR2` are the two POSIX reserves for
//! exactly this, and both already existed as a *hazard*: their default action
//! is **terminate**, so before this change an operator who tried one killed the
//! server. Now they are handled.
//!
//! # Which way the acknowledgement is ordered, and why
//!
//! The line that says the level changed is emitted **under the more verbose of
//! the two filters**: after the reload when going up, before it when coming
//! back down. Emitting it after the reload in both directions would mean the
//! `USR2` acknowledgement was written under the quieter filter and could be the
//! one line the operator needed and did not get.
//!
//! It is honest about its limit: a server started with `RUST_LOG=error` sees no
//! acknowledgement when it returns to that rung, because nothing at `warn` is
//! printable there. It still sees the two going up.
//!
//! # What reloading costs
//!
//! [`tracing_subscriber::reload`] disables `tracing`'s callsite interest cache
//! for the layer it wraps, so a filter decision is made per event rather than
//! once per callsite. That is a real cost and it is paid on every gunnar
//! process, not only on one that ever receives a signal. It is taken because
//! the alternative is a server an operator cannot look inside, and because
//! `tracing`'s **global** max-level short-circuit still applies: a `debug!`
//! callsite under an `info` filter is not evaluated at all. `Handle::reload`
//! rebuilds that cache, which is what makes a raise take effect on callsites
//! that were dead a moment ago.

use std::io::IsTerminal;
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::OnceLock;

use tracing_subscriber::layer::SubscriberExt as _;
use tracing_subscriber::util::SubscriberInitExt as _;
use tracing_subscriber::{reload, EnvFilter, Registry};

/// The `tracing` target the level changes are announced on.
///
/// `gunnar::metrics` is the heartbeat's target — *what this server is doing
/// right now* — and a level change is exactly that: state of the running
/// process, not a transfer and not a control-plane decision. It also means an
/// operator already filtering for the heartbeat sees their own signal land.
pub const TARGET: &str = "gunnar::metrics";

/// The verbosity ladder `SIGUSR1` walks.
///
/// Rung 0 is whatever the process started with, so the cycle always returns to
/// the configuration the deployment chose rather than to a value this file
/// picked. Rungs 1 and 2 are **bare** levels and not `gunnar=debug`: an
/// operator reaching for `debug` at 03:00 usually needs to see `russh`, `gix`
/// and `h2` as well, and a rung that quietly excluded them would be a rung that
/// answers the wrong question.
const RUNGS: usize = 3;

/// The name of each rung, for the acknowledgement line.
fn rung_name(rung: usize, startup: &str) -> String {
    match rung {
        0 => format!("{startup} (the startup filter)"),
        1 => "debug".to_owned(),
        _ => "trace".to_owned(),
    }
}

/// The filter directive each rung installs.
fn rung_spec(rung: usize, startup: &str) -> String {
    match rung {
        0 => startup.to_owned(),
        1 => "debug".to_owned(),
        _ => "trace".to_owned(),
    }
}

/// The live filter, and what the process started with.
struct LogControl {
    handle: reload::Handle<EnvFilter, Registry>,
    /// The startup directive, rung 0. Kept as the **string** rather than as an
    /// `EnvFilter`, because `EnvFilter` is not `Clone` and rung 0 has to be
    /// re-buildable every time the cycle comes back round to it.
    startup: String,
    rung: AtomicUsize,
}

static CONTROL: OnceLock<LogControl> = OnceLock::new();

/// Install the subscriber, once, with a reloadable filter.
///
/// Returns `false` when another subscriber was already global — a test binary
/// installs its own — in which case there is nothing to reload and
/// [`cycle`]/[`reset`] say so rather than reporting a change that did not
/// happen.
/// **The startup filter**: `RUST_LOG` (else `info`/`debug`), with boringtun's timer lines
/// silenced unless the operator named boringtun — `HANDSHAKE(REKEY_TIMEOUT)` every 5 s at
/// WARN and `CONNECTION_EXPIRED` at ERROR for a peer that is merely rebooting (release-3
/// test2). The data plane says the peer's state itself (edda wg-appliance-core).
///
/// And rustls's complaints about a PEER's ClientHello (`rustls::msgs::handshake`: an IP address
/// presented as the SNI host name, a duplicate or malformed SNI) are said only from the debug
/// rung up, unless the operator named rustls: every scanner that dials the front's bare IP
/// sends its IP as SNI, and rustls said that at WARN per handshake (R5.1-E, test2 r4 + r5:
/// bursts of 10, ~7/min over a day). The handshake goes on (rustls ignores the name), the
/// access line still says what the scanner asked for, and nothing about it is ours to grade.
pub fn startup_filter(rust_log: Option<&str>, verbose: bool) -> String {
    let default = if verbose { "debug" } else { "info" };
    let mut filter = rust_log.map(str::trim).filter(|v| !v.is_empty()).unwrap_or(default).to_owned();
    if !filter.contains("boringtun") {
        filter.push_str(",boringtun::noise::timers=off");
    }
    if !filter.contains("rustls") {
        filter.push_str(",rustls::msgs::handshake=error");
    }
    filter
}

/// **Rung 0, twice**: the filter as the OPERATOR set it (`RUST_LOG`, else `info`/`debug`,
/// as `EnvFilter` spells it; a malformed one degrades to the default) — what rung 0 is
/// NAMED — and the filter rung 0 is BUILT from ([`startup_filter`]: with boringtun's timer
/// lines silenced). The acknowledgement says `level=info`, never the silence.
pub(crate) fn startup_parts(rust_log: Option<&str>, verbose: bool) -> (String, String) {
    let default = if verbose { "debug" } else { "info" };
    let base = rust_log.map(str::trim).filter(|v| !v.is_empty()).unwrap_or(default);
    let operator = EnvFilter::try_new(base).map(|f| f.to_string()).unwrap_or_else(|_| default.to_owned());
    let built = startup_filter(Some(&operator), verbose);
    (operator, built)
}

/// The filter rung `rung` is BUILT from: rung 0 carries the boringtun silence
/// ([`startup_filter`]); the upper rungs are what an operator asking for debug or trace wants,
/// all of it.
pub(crate) fn built(rung: usize, startup: &str) -> String {
    match rung {
        0 => startup_filter(Some(startup), false),
        _ => rung_spec(rung, startup),
    }
}

pub fn init(verbose: bool) -> bool {
    let (startup, spec) = startup_parts(std::env::var("RUST_LOG").ok().as_deref(), verbose);
    // Parsed once here so a malformed `RUST_LOG` degrades to the default
    // exactly as `try_from_default_env` used to, rather than aborting a server.
    let filter = EnvFilter::try_new(&spec).unwrap_or_else(|_| EnvFilter::new(built(0, if verbose { "debug" } else { "info" })));

    let (filter_layer, handle) = reload::Layer::new(filter);
    let format_layer = tracing_subscriber::fmt::layer()
        // ── colour only when a human is watching ────────────────────────────
        //
        // `tracing_subscriber::fmt`'s ANSI default is `cfg!(feature = "ansi")`,
        // which is on and is **not** conditioned on the writer being a
        // terminal. So every line gunnar wrote into a redirect, a pipe, a unit's
        // journal or a `podman logs` capture carried SGR escapes — and they wrap
        // the *field names*, not only the colours around them, so a captured
        // line reads `\x1b[3mbytes_out\x1b[0m\x1b[2m=\x1b[0m8170`.
        //
        // That is not cosmetic. `grep bytes_out=` over a captured log matches
        // **nothing**, and a pipeline that sums the matches reports a confident
        // zero rather than an error — which is exactly the shape of a clean
        // result. The Fet Kaos Monkey rig hit it on 2026-08-05 and the
        // measurement it silently produced was a total of 0 bytes served.
        //
        // A flag would leave the default wrong; asking the descriptor makes the
        // log an operator captures plain by construction, and leaves the
        // interactive one coloured.
        //
        // [`at_a_pty`] and not `is_terminal()`, for the same reason the writer
        // gate below is: the appliance's `/dev/console` IS a terminal, and
        // colouring it spends ~90 bytes of SGR per line on the 115 200-baud
        // line that is already the narrowest thing on the box — bytes that buy
        // nobody a colour, because the log anyone ever reads off an appliance
        // is a *captured* serial log.
        .with_ansi(at_a_pty());

    // `try_init` rather than `init`: a test process may install its own, and a
    // second install must not abort the program.
    // The tap sits AFTER the filter and beside the formatter: the same rung
    // that governs stderr governs what the console dashboard sees.
    //
    // ── the console is written by ONE thread, never by a request ────────────
    //
    // Anything that is not a **pty** — the appliance's serial console (PID 1),
    // journald, a file, a test's pipe — goes through [`crate::logqueue`], and
    // the thread that logged the line carries on. MEASURED 2026-08-30:
    // on the KVM rig the paced 115200-baud UART cost every push 8–50 ms PER
    // LINE written synchronously from the connection thread — the whole of
    // gunnar's 2.8× deficit against stock git on push-create, and the reason
    // eight parallel clients serialised at 7 ops/s.
    //
    // The gate is [`at_a_pty`] and NOT `is_terminal()`, and that difference is
    // the entire fix. `/dev/console` and `/dev/ttyS0` are character devices for
    // which `isatty(2)` is **true**, so an `is_terminal()` gate excluded the
    // appliance from the one fix written for it. Measured that way — queue
    // shipped, gate `is_terminal()` — the appliance's push-create numbers did
    // not move by a millisecond: 200 sequential in 34.84 s against 35.25 s with
    // no queue at all (`phase-noqueue.tsv`). A pty is where a human is,
    // and there the synchronous writer stays: `println!` interleaving with the
    // log in order is worth more than a few microseconds a line.
    let installed = if at_a_pty() {
        Registry::default()
            .with(filter_layer)
            .with(crate::logtap::TapLayer::new())
            .with(format_layer.with_writer(std::io::stderr))
            .try_init()
            .is_ok()
    } else {
        Registry::default()
            .with(filter_layer)
            .with(crate::logtap::TapLayer::new())
            .with(format_layer.with_writer(crate::logqueue::install(crate::logqueue::console_sink())))
            .try_init()
            .is_ok()
    };
    if !installed {
        return false;
    }
    // Only recorded once the subscriber is actually ours. A handle to a
    // subscriber that was never installed reloads nothing and would report
    // success, which is the vacuous green this whole suite is written against.
    let _ = CONTROL.set(LogControl {
        handle,
        startup,
        rung: AtomicUsize::new(0),
    });
    true
}

/// Whether stderr is a **pty** — a terminal emulator, an `ssh` session, a
/// `tmux` pane — as opposed to a console, a file, a pipe or a journal.
///
/// # Why this exists and `is_terminal()` does not do
///
/// `is_terminal()` answers *"is this a tty?"*, and on Linux the answer is
/// **yes** for `/dev/console`, `/dev/ttyS0` and the VGA virtual consoles.
/// Those are precisely the devices a request thread must never wait for: the
/// appliance's stderr is `/dev/console`, a 16550 UART the hypervisor paces at
/// its declared 115 200 baud, ~30 KB/s. Gating the console queue on
/// `is_terminal()` therefore left the appliance out of its own fix, and the
/// measurement said so plainly — see the writer gate in [`init_with_default`].
///
/// A pty is the one terminal that is fast and that a human is actually looking
/// at, and on Linux it is exactly the UNIX98 `pts` driver: character major
/// **136–143**. The device behind the descriptor is read from
/// `/proc/self/fd/2`, which resolves to the real device however stderr was
/// inherited or redirected. A box with no `/proc` falls back to
/// `is_terminal()` — the pre-2026-08-30 behaviour, never worse than it.
fn at_a_pty() -> bool {
    if !std::io::stderr().is_terminal() {
        // Not a tty at all: a file, a pipe, journald, a test harness. A pipe
        // nobody is reading blocks a writer exactly as a UART does, so this
        // side takes the queue too.
        return false;
    }
    let Ok(meta) = std::fs::metadata("/proc/self/fd/2") else {
        return true;
    };
    is_pty_device(std::os::linux::fs::MetadataExt::st_rdev(&meta))
}

/// The device half of [`at_a_pty`], separated so it can be given the device
/// numbers of a console and of a pty and made to disagree about them.
///
/// `st_rdev`'s encoding is glibc's `makedev`, spelled out rather than linked:
/// this arithmetic is the whole decision and a reader has to be able to check
/// it where it is made.
fn is_pty_device(rdev: u64) -> bool {
    let major = ((rdev >> 8) & 0xfff) | ((rdev >> 32) & !0xfff);
    (136..=143).contains(&major)
}

/// The filter this process is running under right now, or `None` when gunnar
/// did not install the subscriber.
pub fn current() -> Option<String> {
    let control = CONTROL.get()?;
    Some(rung_spec(
        control.rung.load(Ordering::Relaxed),
        &control.startup,
    ))
}

/// One rung more verbose, wrapping back to the startup filter.
///
/// Returns the filter now in force, or `None` when gunnar did not install the
/// subscriber.
pub fn cycle() -> Option<String> {
    let control = CONTROL.get()?;
    let next = (control.rung.load(Ordering::Relaxed) + 1) % RUNGS;
    apply(control, next)
}

/// Straight back to the startup filter, from wherever the cycle is.
///
/// Not reachable by cycling in one step, and that is the point: an operator who
/// has turned `trace` on during an incident wants it off **now**, not after two
/// more signals, and a `trace` server under load is a server writing more log
/// than it serves git.
pub fn reset() -> Option<String> {
    let control = CONTROL.get()?;
    apply(control, 0)
}

/// Install rung `next`, announcing it under whichever of the two filters is the
/// more verbose. See the module docs.
fn apply(control: &LogControl, next: usize) -> Option<String> {
    let previous = control.rung.load(Ordering::Relaxed);
    let spec = rung_spec(next, &control.startup);
    let name = rung_name(next, &control.startup);
    let filter = EnvFilter::try_new(built(next, &control.startup)).ok()?;

    let quieter = next < previous;
    if quieter {
        announce(&name, previous, &control.startup);
    }
    // `reload` rebuilds `tracing`'s interest cache, which is what makes a
    // `debug!` callsite that was dead under `info` start firing.
    control.handle.reload(filter).ok()?;
    control.rung.store(next, Ordering::Relaxed);
    if !quieter {
        announce(&name, next, &control.startup);
    }
    Some(spec)
}

/// The acknowledgement. `warn`, because it must survive the quietest filter an
/// operator is realistically running, and because a level change on a
/// production box is worth a raised eyebrow in the log a week later.
fn announce(now: &str, under: usize, startup: &str) {
    tracing::warn!(
        target: TARGET,
        event = "log.level",
        level = %now,
        // What the OTHER two signals will do from here, so the operator does
        // not have to remember which is which at 03:00.
        usr1 = "one rung more verbose",
        usr2 = %format!("back to {}", rung_spec(0, startup)),
        "gunnar's log level changed"
    );
    debug_assert!(under < RUNGS);
}

// ───────────────────────────────────────────────────────────────────────────
// The signals
// ───────────────────────────────────────────────────────────────────────────

/// Handle `SIGUSR1` and `SIGUSR2` for the life of the process.
///
/// Spawned by `gunnar serve`. **Not** joined and not cancelled: a level-control
/// task that stopped with the server it was watching would be one more thing to
/// get wrong at shutdown, and the task holds nothing but two signal streams.
///
/// If either stream cannot be registered the task says so **once, at `warn`,
/// and exits**, rather than looping. A server that silently did not handle
/// `SIGUSR1` would kill itself the first time an operator tried one, which is
/// the default disposition of that signal and the reason this is worth a line.
#[cfg(feature = "server")]
pub fn spawn_signal_control() -> tokio::task::JoinHandle<()> {
    use tokio::signal::unix::{signal, SignalKind};

    // A32-14, stays a task: a signal listener for the life of the runtime; it ends with it.
    tokio::spawn(async move {
        let (mut usr1, mut usr2) = match (
            signal(SignalKind::user_defined1()),
            signal(SignalKind::user_defined2()),
        ) {
            (Ok(one), Ok(two)) => (one, two),
            _ => {
                tracing::warn!(
                    target: TARGET,
                    "SIGUSR1/SIGUSR2 could not be registered, so this server's log level cannot \
                     be changed without restarting it. Note that the DEFAULT disposition of both \
                     signals is to terminate the process: do not send them to this one."
                );
                return;
            }
        };
        if CONTROL.get().is_none() {
            tracing::warn!(
                target: TARGET,
                "the tracing subscriber was installed by something other than gunnar, so \
                 SIGUSR1/SIGUSR2 will be absorbed and will change nothing."
            );
        }
        loop {
            let changed = tokio::select! {
                _ = usr1.recv() => cycle(),
                _ = usr2.recv() => reset(),
            };
            if changed.is_none() {
                tracing::warn!(
                    target: TARGET,
                    "a log-level signal arrived and there is no reloadable filter to move"
                );
            }
        }
    })
}

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

    /// The ladder is a **cycle** and rung 0 is the startup filter, not a
    /// hard-coded `info`.
    ///
    /// Seen red: with `rung_spec`'s arm 0 returning `"info"` instead of
    /// `startup`, a server started at `RUST_LOG=warn,gunnar::git=info` would
    /// come back from `trace` **louder** than it started, and this fails.
    #[test]
    fn the_ladder_returns_to_what_the_process_started_with() {
        let startup = "warn,gunnar::git=info";
        assert_eq!(rung_spec(0, startup), startup);
        assert_eq!(rung_spec(1, startup), "debug");
        assert_eq!(rung_spec(2, startup), "trace");
        // …and it wraps rather than saturating, or `USR1` from `trace` would be
        // a signal that does nothing and reads as a broken handler.
        assert_eq!((2 + 1) % RUNGS, 0);
        // Every rung is nameable; an unnamed rung would print an empty `level=`.
        for rung in 0..RUNGS {
            assert!(!rung_name(rung, startup).is_empty());
            assert!(!rung_spec(rung, startup).is_empty());
        }
    }

    /// Rungs 1 and 2 are strictly more verbose than anything a deployment sets,
    /// which is what makes the acknowledgement visible on the way up.
    #[test]
    fn the_upper_rungs_are_bare_levels_and_not_gunnar_only() {
        for rung in 1..RUNGS {
            let spec = rung_spec(rung, "info");
            assert!(
                !spec.contains('='),
                "rung {rung} is a targeted directive ({spec}), so an operator who asked for \
                 debug would not see russh, gix or h2 — the crates a transport incident is \
                 usually in"
            );
            assert!(EnvFilter::try_new(&spec).is_ok(), "{spec} does not parse");
        }
    }

    /// The gate that put the console queue on the wrong side of the appliance
    /// for a whole release: a serial console IS a terminal.
    ///
    /// # Seen red
    ///
    /// With `is_pty_device` written the way the gate used to think — "a tty is
    /// a tty" — every one of these device numbers answers `true` and the two
    /// `/dev/console` assertions fail. That is the bug this reproduces: the
    /// appliance shipped with `logqueue` compiled in and never installed, and
    /// 200 sequential push-creates took 34.84 s with it and 35.25 s without.
    #[test]
    fn a_serial_console_is_a_terminal_and_is_not_a_pty() {
        // glibc `makedev(major, minor)` for the devices that matter.
        let dev = |major: u64, minor: u64| {
            ((major & 0xfff) << 8)
                | ((major & !0xfffu64) << 32)
                | (minor & 0xff)
                | ((minor & !0xffu64) << 12)
        };
        // What the appliance's stderr actually is (PID 1, `console=ttyS0`).
        assert!(
            !is_pty_device(dev(5, 1)),
            "/dev/console must take the queue"
        );
        // A unit with `StandardError=tty` on the UART, and the UART itself.
        assert!(!is_pty_device(dev(4, 64)), "/dev/ttyS0 must take the queue");
        assert!(!is_pty_device(dev(4, 65)), "/dev/ttyS1 must take the queue");
        // The VGA virtual consoles: a tty, scrolled by the kernel, not a pty.
        assert!(!is_pty_device(dev(4, 1)), "/dev/tty1 must take the queue");
        // A human in a terminal emulator, an ssh session, a tmux pane.
        assert!(is_pty_device(dev(136, 0)), "/dev/pts/0 is where a human is");
        assert!(is_pty_device(dev(136, 5)), "/dev/pts/5 is where a human is");
        assert!(is_pty_device(dev(143, 255)), "the last UNIX98 pts major");
        assert!(!is_pty_device(dev(144, 0)), "past the pts range");
        // And the arithmetic is glibc's, not a guess: ask the kernel for a
        // device it has. `/dev/null` is (1, 3) on every Linux, host or
        // container — a runtime bind-mounts the host's node, it never mints
        // its own — so it is the one device whose number is a constant.
        let rdev_of = |p: &str| {
            std::fs::metadata(p)
                .ok()
                .map(|m| std::os::linux::fs::MetadataExt::st_rdev(&m))
        };
        if let Some(rdev) = rdev_of("/dev/null") {
            assert_eq!(rdev, dev(1, 3), "makedev() is not encoded as assumed");
            assert!(!is_pty_device(rdev), "/dev/null is not a pty");
        }
        // `/dev/console` is (5, 1) — the kernel console — on a booted box,
        // and the appliance's stderr. It is NOT (5, 1) inside a container:
        // LXC, podman and systemd-nspawn bind-mount the pty they allocated
        // for the container's console over `/dev/console`. MEASURED on dwarf
        // 2026-09-29: `crw--w---- 136, 0 /dev/console`, and
        // `/proc/self/mountinfo` has `/0 /dev/console … - devpts devpts`.
        // The old assertion took that for broken makedev() arithmetic. So the
        // container is DETECTED (a devpts mount at /dev/console, read off the
        // kernel's own mount table, not inferred from the number under test)
        // and judged for what it is: a pts, which `is_pty_device` must call
        // a pty — a human attached with `lxc console` is at a terminal
        // emulator, not a UART.
        if let Some(rdev) = rdev_of("/dev/console") {
            if console_is_a_container_pty_bind() {
                assert!(
                    is_pty_device(rdev),
                    "/dev/console is a devpts bind (a container's console), rdev {rdev:#x}, \
                     and is_pty_device did not call it a pty"
                );
            } else {
                assert_eq!(
                    rdev,
                    dev(5, 1),
                    "/dev/console is not a devpts bind, so it is the kernel console (5, 1)"
                );
                assert!(!is_pty_device(rdev), "the real /dev/console is not a pty");
            }
        }
    }

    /// Whether `/dev/console` is a mount of a `devpts` node — the shape every
    /// container runtime gives a container's console. Read off
    /// `/proc/self/mountinfo`.
    fn console_is_a_container_pty_bind() -> bool {
        std::fs::read_to_string("/proc/self/mountinfo")
            .map(|info| console_bind_in(&info))
            .unwrap_or(false)
    }

    /// The decision, on mount-table text: field 5 is the mount point and the
    /// first field after the ` - ` separator is the filesystem type.
    fn console_bind_in(mountinfo: &str) -> bool {
        mountinfo.lines().any(|line| {
            let Some((head, tail)) = line.split_once(" - ") else {
                return false;
            };
            head.split(' ').nth(4) == Some("/dev/console")
                && tail.split(' ').next() == Some("devpts")
        })
    }

    /// The mount-table reader above, on the two lines it has to tell apart —
    /// so the container branch is taken because the table says so, and a
    /// reader that answered `true` for everything would be red here.
    #[test]
    fn a_container_console_is_told_from_the_kernel_console() {
        let container = "692 657 0:79 /0 /dev/console rw,nosuid,noexec,relatime shared:652 - devpts devpts rw,gid=5,mode=620";
        let pts_dir = "690 657 0:79 / /dev/pts rw,nosuid,noexec,relatime shared:650 - devpts devpts rw,gid=5,mode=620";
        // A booted box: the console is the kernel's own node on devtmpfs, and
        // /dev/console is no mount point at all.
        let booted = "22 26 0:5 / /dev rw,nosuid,relatime shared:2 - devtmpfs udev rw,size=8144k";
        assert!(console_bind_in(container));
        assert!(!console_bind_in(pts_dir), "/dev/pts itself is not the console");
        assert!(!console_bind_in(booted), "a devtmpfs /dev is the kernel console's");
        assert!(console_bind_in(&[booted, pts_dir, container].join("\n")));
    }

    /// **boringtun's timer lines are not ours to grade** (release-3 test2 on UpCloud: while
    /// the front rebooted, main and the twin logged `HANDSHAKE(REKEY_TIMEOUT)` WARN 7/min and
    /// `ERROR CONNECTION_EXPIRED`). The startup filter silences `boringtun::noise::timers`;
    /// the data plane says the peer's state itself (edda wg-appliance-core, unreachable/back).
    /// An operator who names boringtun in RUST_LOG gets exactly what they named.
    #[test]
    fn the_startup_filter_silences_boringtuns_timer_lines_unless_rust_log_names_boringtun() {
        assert_eq!(super::startup_filter(None, false), "info,boringtun::noise::timers=off,rustls::msgs::handshake=error");
        assert_eq!(super::startup_filter(Some("warn,gunnar=debug"), false), "warn,gunnar=debug,boringtun::noise::timers=off,rustls::msgs::handshake=error");
        assert_eq!(super::startup_filter(Some("  "), true), "debug,boringtun::noise::timers=off,rustls::msgs::handshake=error");
        assert_eq!(super::startup_filter(Some("info,boringtun=trace"), false), "info,boringtun=trace,rustls::msgs::handshake=error");
    }

    /// **The level acknowledgement names the OPERATOR's filter** (gunnar-cli control_cli
    /// a_signal_changes_a_running_servers_log_level_without_restarting_it RED at 78af74e:
    /// the SIGUSR2 line said `level=info,boringtun::noise::timers=off (the startup filter)`,
    /// never `level=info`). Rung 0 is what the operator set; the boringtun silence is added
    /// only where the filter is BUILT, so it is in force at rung 0 and never named.
    #[test]
    fn rung_zero_is_named_as_the_operator_set_it_and_built_with_the_silence() {
        let (operator, built) = super::startup_parts(None, false);
        assert_eq!(operator, "info");
        assert!(rung_name(0, &operator).starts_with("info "), "{}", rung_name(0, &operator));
        assert_eq!(built, "info,boringtun::noise::timers=off,rustls::msgs::handshake=error");
        assert_eq!(super::built(0, &operator), built, "rung 0 is built with the silence");
        assert_eq!(super::built(1, &operator), "debug", "an operator asking for debug gets all of it");
        let (operator, built) = super::startup_parts(Some("warn"), false);
        assert_eq!((operator.as_str(), built.as_str()), ("warn", "warn,boringtun::noise::timers=off,rustls::msgs::handshake=error"));
    }

    /// How many of `emit`'s events a subscriber filtered by `spec` lets through.
    fn said_under(spec: &str, emit: impl FnOnce()) -> usize {
        use std::sync::atomic::AtomicUsize;
        use std::sync::Arc;
        use tracing_subscriber::layer::{Context, Layer};
        struct Count(Arc<AtomicUsize>);
        impl<S: tracing::Subscriber> Layer<S> for Count {
            fn on_event(&self, _: &tracing::Event<'_>, _: Context<'_, S>) {
                self.0.fetch_add(1, Ordering::Relaxed);
            }
        }
        let n = Arc::new(AtomicUsize::new(0));
        let sub = Registry::default().with(EnvFilter::new(spec)).with(Count(Arc::clone(&n)));
        tracing::subscriber::with_default(sub, emit);
        n.load(Ordering::Relaxed)
    }

    /// **A peer's illegal SNI is not ours to grade** (R5.1-E, test2 r4 and r5 on UpCloud): every
    /// scanner that dials the front's bare IP (`https://95.111.209.187/` then `/.git/config`,
    /// `/wp-config.php.bak`, …) presents that IP as its SNI host name, and rustls says
    /// `WARN rustls::msgs::handshake: Illegal SNI extension: ignoring IP address presented as
    /// hostname` per handshake — bursts of 10, ~7/min over a day, none of it the estate's doing.
    /// Rung 0 does not say it; the debug rung (SIGUSR1) does; an operator who names rustls in
    /// RUST_LOG gets what they named. Our own WARNs and rustls's others are said as before.
    #[test]
    fn a_peers_illegal_sni_is_said_at_the_debug_rung_only() {
        let sni = || tracing::warn!(target: "rustls::msgs::handshake", "Illegal SNI extension: ignoring IP address presented as hostname (39352e3131312e3230392e313837)");
        let (operator, rung0) = super::startup_parts(None, false);
        assert_eq!(said_under(&rung0, sni), 0, "rung 0 ({rung0}) says the peer's SNI");
        assert_eq!(said_under(&super::built(1, &operator), sni), 1, "the debug rung hides it");
        let named = super::startup_filter(Some("info,rustls=debug"), false);
        assert_eq!(said_under(&named, sni), 1, "RUST_LOG named rustls ({named}) and still lost it");
        let (_, warn0) = super::startup_parts(Some("warn"), false);
        assert_eq!(said_under(&warn0, sni), 0, "rung 0 under RUST_LOG=warn ({warn0}) says it");
        assert_eq!(said_under(&rung0, || tracing::warn!(target: "gunnar::twin", "ours")), 1, "our WARN went quiet");
        assert_eq!(said_under(&rung0, || tracing::warn!(target: "rustls::common_state", "TLS alert warning received")), 1, "rustls's other WARNs went quiet");
    }
}