crates/gunnar-common/src/logging.rs
//! **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"
);
}
}