diff --git a/crates/bugwarden/src/config.rs b/crates/bugwarden/src/config.rs index 2f8ffd4..9a99876 100644 --- a/crates/bugwarden/src/config.rs +++ b/crates/bugwarden/src/config.rs @@ -445,11 +445,11 @@ mod tests { cli.api_key_file = Some(file.path().to_path_buf()); let (custody, logs) = crate::testlog::capture_logs(|| cli.resolve_key_custody()); drop(custody.expect("key file resolves")); - assert!(logs.contains("server-held"), "startup log: {logs}"); - assert!( - logs.contains(&file.path().display().to_string()), - "the log must name the source path: {logs}" - ); + crate::testlog::assert_logged(&logs, "server-held"); + crate::testlog::assert_logged(&logs, &file.path().display().to_string()); + // The I12 check below is a negative: on its own an empty capture would + // satisfy it. It is evidence only because the positive assertions above + // run first and fail loudly on one — keep them ahead of it. assert!( !logs.contains("hush-key"), "the log must never carry key material (I12): {logs}" @@ -458,9 +458,6 @@ mod tests { let cli = base_cli("http"); let (custody, logs) = crate::testlog::capture_logs(|| cli.resolve_key_custody()); drop(custody.expect("http resolves")); - assert!( - logs.contains("per-request via the 'ApiKey' header"), - "startup log: {logs}" - ); + crate::testlog::assert_logged(&logs, "per-request via the 'ApiKey' header"); } } diff --git a/crates/bugwarden/src/server.rs b/crates/bugwarden/src/server.rs index a509c92..1fb9b76 100644 --- a/crates/bugwarden/src/server.rs +++ b/crates/bugwarden/src/server.rs @@ -3840,6 +3840,10 @@ mod tests { let (server, logs) = crate::testlog::capture_logs(|| BugWarden::new(Arc::new(cli), guard, bz)); drop(server.expect("server must build")); + // The `false` arm asserts an absence, which an empty capture + // satisfies while proving nothing. This is what separates "the + // warning was not emitted" from "nothing was captured at all". + crate::testlog::assert_captured(&logs); assert_eq!( logs.contains("created_by_me describes that one account"), expect_warn, diff --git a/crates/bugwarden/src/testlog.rs b/crates/bugwarden/src/testlog.rs index 3f820d8..24d74b2 100644 --- a/crates/bugwarden/src/testlog.rs +++ b/crates/bugwarden/src/testlog.rs @@ -1,19 +1,29 @@ //! Test-only capture of tracing output, for pinning what startup log lines //! say — and, per I12, what they must never say. +use std::cell::RefCell; use std::io::Write; -use std::sync::{Arc, Mutex}; +use std::sync::Once; -/// Cloneable in-memory writer handed to the fmt subscriber. -#[derive(Clone, Default)] -struct Buffer(Arc>>); +thread_local! { + /// Where the calling thread's capture accumulates. `None` means this + /// thread is not capturing, and its events are dropped on the floor. + static CAPTURE: RefCell>> = const { RefCell::new(None) }; +} + +/// Writer handed to the process-wide subscriber. Appends to the calling +/// thread's capture, so parallel tests cannot splice events into each other's. +struct ThreadCapture; -impl Write for Buffer { +impl Write for ThreadCapture { fn write(&mut self, buf: &[u8]) -> std::io::Result { - self.0 - .lock() - .expect("log buffer lock") - .extend_from_slice(buf); + // `try_with`, not `with`: a thread may still log while its + // thread-locals are being torn down, and that must not panic. + let _ = CAPTURE.try_with(|slot| { + if let Some(capture) = slot.borrow_mut().as_mut() { + capture.extend_from_slice(buf); + } + }); Ok(buf.len()) } @@ -22,18 +32,137 @@ impl Write for Buffer { } } -/// Run `f` with a fresh fmt subscriber as the thread-default and return its -/// result together with everything it logged. +/// Install the capturing subscriber as the process-wide default, once. +/// +/// It has to be a permanent global default rather than a `with_default` scoped +/// to each capture. `tracing` caches a callsite's `Interest` the first time the +/// callsite is hit, computed from the *registering* thread's default subscriber +/// — as of tracing-core 0.1.36 the std `Dispatchers::rebuilder` takes its +/// `has_just_one` fast path and simply asks `dispatcher::get_default`. Under +/// parallel tests a thread running some other test — with no subscriber of its +/// own — can win that race and cache `Interest::never()`, after which the +/// `info!` macro short-circuits without ever consulting a dispatcher and every +/// later capture of that callsite comes back empty (issue #92). Once this +/// global default is visible, every such registration resolves to it instead. +/// +/// The explicit rebuild closes the gap installation itself opens: setting the +/// global default raises the global max level to TRACE while building the +/// `Dispatch`, but only publishes the subscriber afterwards, and it never +/// rebuilds. A callsite first hit in between passes `level_enabled!` and still +/// resolves to no subscriber, so it caches `never` with nothing left to correct +/// it; the rebuild recomputes everything registered while the default was +/// invisible. +/// +/// Consequence worth knowing: from the first capture onwards the process-wide +/// max level stays TRACE, so every tracing macro in every later test evaluates +/// its fields and is formatted before `ThreadCapture` discards it, where before +/// it short-circuited. Field side effects are live across the whole binary. +fn install() { + static INSTALLED: Once = Once::new(); + INSTALLED.call_once(|| { + let subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::TRACE) + .with_ansi(false) + .with_writer(|| ThreadCapture) + .finish(); + tracing::subscriber::set_global_default(subscriber) + .expect("the capturing subscriber must be this test process's only global default"); + tracing::callsite::rebuild_interest_cache(); + }); +} + +/// Run `f` with everything it logs *on this thread* captured, and return its +/// result together with the captured output. Events emitted meanwhile by other +/// threads go to their own (absent) capture and are discarded. +/// +/// Captures do not nest: an inner call would hand the outer one an empty +/// string, so a nested capture is a debug assertion rather than a silent loss. pub(crate) fn capture_logs(f: impl FnOnce() -> T) -> (T, String) { - let buffer = Buffer::default(); - let writer = buffer.clone(); - let subscriber = tracing_subscriber::fmt() - .with_max_level(tracing::Level::TRACE) - .with_ansi(false) - .with_writer(move || writer.clone()) - .finish(); - let value = tracing::subscriber::with_default(subscriber, f); - let logs = String::from_utf8(buffer.0.lock().expect("log buffer lock").clone()) - .expect("captured logs are UTF-8"); + install(); + CAPTURE.with(|slot| { + let mut slot = slot.borrow_mut(); + debug_assert!( + slot.is_none(), + "capture_logs does not nest: the inner capture would swallow the outer one" + ); + *slot = Some(Vec::new()); + }); + let value = f(); + let captured = CAPTURE + .with(|slot| slot.borrow_mut().take()) + .unwrap_or_default(); + let logs = String::from_utf8(captured).expect("captured logs are UTF-8"); (value, logs) } + +/// Assert that the capture is not empty. +/// +/// Nothing captured is a different defect from a message that came out wrong — +/// it means the subscriber saw no events at all — and it must be reported as +/// such instead of surfacing as a bare "expected text missing" against an +/// empty haystack. It is also what makes the negative I12 assertions evidence: +/// "the log must never carry the key" holds vacuously over an empty capture. +#[track_caller] +pub(crate) fn assert_captured(logs: &str) { + assert!( + !logs.is_empty(), + "captured nothing: the subscriber saw no events" + ); +} + +/// Assert that the capture carries `needle`, distinguishing an empty capture +/// from one that merely lacks the text. +#[track_caller] +pub(crate) fn assert_logged(logs: &str, needle: &str) { + assert_captured(logs); + assert!( + logs.contains(needle), + "captured logs lack {needle:?}: {logs}" + ); +} + +#[cfg(test)] +mod tests { + use super::*; + + const PROBE: &str = "testlog-interest-probe"; + + /// Both hits below must be the *same* callsite, so the emit lives in one + /// function rather than being written out twice. + fn probe() { + tracing::info!("{PROBE}"); + } + + #[test] + fn a_subscriberless_thread_cannot_silence_a_later_capture() { + // Registering the callsite from a subscriber-less thread *inside* the + // capture is the deterministic form of the race a parallel test run + // used to lose: with a scoped `with_default` the interest cached there + // was `never` and the emit below vanished (issue #92). + let (_, logs) = capture_logs(|| { + std::thread::spawn(probe).join().expect("probe thread"); + probe(); + }); + assert_logged(&logs, PROBE); + // Exactly one hit: the other thread's emit belongs to its own capture, + // not to this one. + assert_eq!( + logs.matches(PROBE).count(), + 1, + "only this thread's events belong in the capture: {logs}" + ); + } + + /// An empty capture must be reported as one, not as a missing needle. + #[test] + #[should_panic(expected = "captured nothing")] + fn an_empty_capture_fails_as_an_empty_capture() { + assert_logged("", "anything"); + } + + #[test] + #[should_panic(expected = "captured logs lack")] + fn a_non_empty_capture_without_the_needle_fails_as_a_missing_needle() { + assert_logged("something else entirely", "anything"); + } +}