gam_runtime/
test_support.rs

1//! Test-side backend for the diagnostics production already emits.
2//!
3//! Production instruments its solvers through the `log` facade — the BMS
4//! intercept-solve counters, the GL-ladder rung histogram, the cell-moment cache
5//! stats, the certificate-bound discriminator. Every one of those is a
6//! `log::info!`, and **the `log` facade drops every record until some binary
7//! installs a backend**. No test binary in this workspace installed one, so all
8//! of that instrumentation has been running and producing nothing, in unit tests
9//! and integration tests alike. Two lanes independently spent hours re-deriving
10//! facts these lines already carried (#2472's non-terminating marginal-slope
11//! cluster; the `[CERTIFICATE-BOUND]` discriminator). This module is the missing
12//! half.
13//!
14//! It lives in `gam-runtime` rather than `gam-test-support` for the reason that
15//! crate's own header gives: a helper owning no model-layer type belongs in a
16//! leaf, so depending on it does not drag the solver stack into an unrelated
17//! test build. `gam-runtime` already owns the observability modules (`span`,
18//! `process_monitor`, `loop_progress`) and already depends on `log`.
19//! `gam-test-support` re-exports it for consumers that use that path.
20//!
21//! Following the workspace convention for `test_support` modules, this is a
22//! plain always-compiled `pub mod`: a `cfg(test)` gate would make it invisible
23//! to exactly the downstream integration binaries that need it.
24
25use std::io::Write;
26use std::sync::Once;
27use std::sync::atomic::{AtomicUsize, Ordering};
28
29/// Records that could not be written to stderr.
30///
31/// A logger that silently fails to emit is the exact defect this module exists
32/// to remove, so the failures are counted rather than discarded — panicking
33/// inside `log::Log::log` is not an option (it runs from arbitrary call sites,
34/// including ones holding locks), but going quiet is what got us here.
35/// [`diagnostic_write_failures`] lets a caller assert its diagnostics actually
36/// reached the stream.
37static WRITE_FAILURES: AtomicUsize = AtomicUsize::new(0);
38
39/// Writes every record at or above `Info` straight to stderr, one line at a
40/// time, flushing each.
41///
42/// Per-record flushing is the whole point rather than an inefficiency: the
43/// diagnostics worth reading belong to runs that do not finish. A test killed at
44/// the per-test cap, or a fit abandoned after hours, must leave its trace
45/// behind — buffering it into a summary that never prints is how 17 core-hours
46/// produced zero lines.
47struct StderrDiagnosticLogger;
48
49impl log::Log for StderrDiagnosticLogger {
50    fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
51        metadata.level() <= log::Level::Info
52    }
53
54    fn log(&self, record: &log::Record<'_>) {
55        if !self.enabled(record.metadata()) {
56            return;
57        }
58        // `record.args()` is formatted through `Display`, never `Debug`: the
59        // ban scanner rejects `{:?}` in `eprintln!`/`eprint!`, and a debug-format
60        // diagnostic is unreadable anyway.
61        let mut stderr = std::io::stderr().lock();
62        let written = writeln!(stderr, "[{}] {}", record.level(), record.args());
63        // Flush per record: the diagnostics worth reading belong to runs that do
64        // not finish, so a buffered line is a lost line.
65        let flushed = stderr.flush();
66        if written.is_err() || flushed.is_err() {
67            WRITE_FAILURES.fetch_add(1, Ordering::Relaxed);
68        }
69    }
70
71    fn flush(&self) {
72        if std::io::stderr().flush().is_err() {
73            WRITE_FAILURES.fetch_add(1, Ordering::Relaxed);
74        }
75    }
76}
77
78static DIAGNOSTIC_LOGGER: StderrDiagnosticLogger = StderrDiagnosticLogger;
79static INSTALL_ONCE: Once = Once::new();
80
81/// Install the stderr diagnostic backend for this process, once.
82///
83/// Call it from any test that wants to read production's `log::info!` output.
84/// It is safe to call from every test in a binary and from several binaries at
85/// once: `log::set_logger` may only be called once per process, so the work is
86/// behind a [`Once`], and a losing call is treated as success — some other
87/// backend is already receiving the records, which is the outcome the caller
88/// wanted.
89///
90/// The level is chosen in code (`Info`) and is deliberately not configurable
91/// from the environment: the workspace bans environment-dependent behaviour, and
92/// a diagnostic you have to know an env var to see is one nobody sees.
93pub fn install_diagnostic_logger() {
94    INSTALL_ONCE.call_once(|| {
95        if log::set_logger(&DIAGNOSTIC_LOGGER).is_ok() {
96            log::set_max_level(log::LevelFilter::Info);
97        }
98    });
99}
100
101/// How many records this backend failed to write.
102///
103/// Nonzero means diagnostics were lost, which for a run being read for its
104/// instrumentation is a failed measurement rather than a cosmetic problem.
105pub fn diagnostic_write_failures() -> usize {
106    WRITE_FAILURES.load(Ordering::Relaxed)
107}
108
109#[cfg(test)]
110mod tests {
111    use super::*;
112
113    #[test]
114    fn install_is_idempotent_and_enables_info() {
115        install_diagnostic_logger();
116        install_diagnostic_logger();
117        // The facade only forwards records at or below the max level; if the
118        // install silently did nothing, production's `log::info!` diagnostics
119        // stay invisible and every caller of this module is misled.
120        assert!(
121            log::max_level() >= log::LevelFilter::Info,
122            "diagnostic logger must leave Info records enabled, got {}",
123            log::max_level()
124        );
125        assert!(log::log_enabled!(log::Level::Info));
126    }
127}
gam_runtime/test_support.rs

gam_runtime/
test_support.rs
