diff --git a/crates/bugwarden/src/config.rs b/crates/bugwarden/src/config.rs index 58912b7..26eed7c 100644 --- a/crates/bugwarden/src/config.rs +++ b/crates/bugwarden/src/config.rs @@ -571,13 +571,7 @@ mod tests { drop(custody.expect("key file resolves")); 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}" - ); + logs.assert_not_contains("hush-key"); let cli = base_cli("http"); let (custody, logs) = crate::testlog::capture_logs(|| cli.resolve_key_custody()); diff --git a/crates/bugwarden/src/http_auth.rs b/crates/bugwarden/src/http_auth.rs index 2df5f07..5070141 100644 --- a/crates/bugwarden/src/http_auth.rs +++ b/crates/bugwarden/src/http_auth.rs @@ -772,17 +772,15 @@ mod tests { }); // Five refusals, three lines: 1, 2, 4. A mutation that logged every // refusal — an unauthenticated log-volume lever — fails here. + let text = logs.as_str(); assert_eq!( - logs.matches("http bearer authentication refused a request") + text.matches("http bearer authentication refused a request") .count(), 3, - "{logs}" - ); - assert!(logs.contains("refused=4"), "{logs}"); - assert!( - !logs.contains(WRITE), - "the log must carry no token (I12): {logs}" + "{text}" ); + crate::testlog::assert_logged(&logs, "refused=4"); + logs.assert_not_contains(WRITE); } #[test] @@ -795,14 +793,13 @@ mod tests { ] { let auth = HttpAuth::resolve(&e, insecure).expect("resolve"); let ((), logs) = crate::testlog::capture_logs(|| auth.log_startup_mode()); - // Positive first, so the I12 negative below is evidence and not - // just an empty capture passing. + let text = logs.as_str(); assert!( - logs.contains("http authentication:") || logs.contains("--insecure-no-auth"), - "{logs}" + text.contains("http authentication:") || text.contains("--insecure-no-auth"), + "{text}" ); - assert!(!logs.contains(WRITE), "{logs}"); - assert!(!logs.contains(READ), "{logs}"); + logs.assert_not_contains(WRITE); + logs.assert_not_contains(READ); } } diff --git a/crates/bugwarden/src/server.rs b/crates/bugwarden/src/server.rs index d512579..b69dbaa 100644 --- a/crates/bugwarden/src/server.rs +++ b/crates/bugwarden/src/server.rs @@ -4033,14 +4033,15 @@ 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". + // The `false` arm asserts an absence; as_str has already + // rejected a silent capture, so this is "not emitted" not + // "nothing captured". crate::testlog::assert_captured(&logs); + let text = logs.as_str(); assert_eq!( - logs.contains("created_by_me describes that one account"), + text.contains("created_by_me describes that one account"), expect_warn, - "startup logs: {logs}" + "startup logs: {text}" ); } } diff --git a/crates/bugwarden/src/testlog.rs b/crates/bugwarden/src/testlog.rs index 24d74b2..7806a17 100644 --- a/crates/bugwarden/src/testlog.rs +++ b/crates/bugwarden/src/testlog.rs @@ -71,13 +71,58 @@ fn install() { }); } +/// Logs captured by [`capture_logs`]. +/// +/// There is no `Deref` and no `contains`. The text is reachable +/// only through a path that has already established the capture is non-empty +/// ([`assert_logged`], [`Self::assert_not_contains`], or [`Self::as_str`], +/// which panics on empty). A negative I12 check over a silent capture +/// therefore cannot compile, let alone pass. +#[derive(Debug)] +pub(crate) struct Captured(String); + +impl Captured { + /// The captured text. Panics if the subscriber saw no events. + #[track_caller] + pub(crate) fn as_str(&self) -> &str { + assert_captured(self); + &self.0 + } + + /// Assert that a non-empty capture does not contain `needle`. + /// + /// An empty capture fails as "captured nothing", not as a successful + /// absence. That is what makes a negative I12 check evidence. + #[track_caller] + pub(crate) fn assert_not_contains(&self, needle: &str) { + let logs = self.as_str(); + assert!( + !logs.contains(needle), + "captured logs must not contain {needle:?}: {logs}" + ); + } +} + +/// Clears the thread-local capture slot, including when `f` panics, so the +/// next capture on this thread cannot inherit residue. The `debug_assert!` +/// on entry then only has to reject nesting, not also clean up a crash. +struct ClearCaptureOnDrop; + +impl Drop for ClearCaptureOnDrop { + fn drop(&mut self) { + let _ = CAPTURE.try_with(|slot| { + slot.borrow_mut().take(); + }); + } +} + /// 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) { +/// capture, so a nested capture is a debug assertion rather than a silent loss. +pub(crate) fn capture_logs(f: impl FnOnce() -> T) -> (T, Captured) { install(); CAPTURE.with(|slot| { let mut slot = slot.borrow_mut(); @@ -87,12 +132,14 @@ pub(crate) fn capture_logs(f: impl FnOnce() -> T) -> (T, String) { ); *slot = Some(Vec::new()); }); + let guard = ClearCaptureOnDrop; let value = f(); let captured = CAPTURE .with(|slot| slot.borrow_mut().take()) .unwrap_or_default(); + drop(guard); let logs = String::from_utf8(captured).expect("captured logs are UTF-8"); - (value, logs) + (value, Captured(logs)) } /// Assert that the capture is not empty. @@ -103,9 +150,9 @@ pub(crate) fn capture_logs(f: impl FnOnce() -> T) -> (T, String) { /// 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) { +pub(crate) fn assert_captured(logs: &Captured) { assert!( - !logs.is_empty(), + !logs.0.is_empty(), "captured nothing: the subscriber saw no events" ); } @@ -113,8 +160,8 @@ pub(crate) fn assert_captured(logs: &str) { /// 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); +pub(crate) fn assert_logged(logs: &Captured, needle: &str) { + let logs = logs.as_str(); assert!( logs.contains(needle), "captured logs lack {needle:?}: {logs}" @@ -147,9 +194,10 @@ mod tests { // Exactly one hit: the other thread's emit belongs to its own capture, // not to this one. assert_eq!( - logs.matches(PROBE).count(), + logs.as_str().matches(PROBE).count(), 1, - "only this thread's events belong in the capture: {logs}" + "only this thread's events belong in the capture: {}", + logs.as_str() ); } @@ -157,12 +205,55 @@ mod tests { #[test] #[should_panic(expected = "captured nothing")] fn an_empty_capture_fails_as_an_empty_capture() { - assert_logged("", "anything"); + assert_logged(&Captured(String::new()), "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"); + assert_logged(&Captured("something else entirely".into()), "anything"); + } + + #[test] + #[should_panic(expected = "captured nothing")] + fn as_str_on_an_empty_capture_fails_as_an_empty_capture() { + let _ = Captured(String::new()).as_str(); + } + + #[test] + #[should_panic(expected = "captured nothing")] + fn assert_not_contains_on_an_empty_capture_fails_as_an_empty_capture() { + Captured(String::new()).assert_not_contains("secret"); + } + + #[test] + #[should_panic(expected = "captured logs must not contain")] + fn assert_not_contains_fails_when_the_needle_is_present() { + Captured("leaked-token-material".into()).assert_not_contains("leaked-token-material"); + } + + #[test] + fn assert_not_contains_accepts_a_non_empty_capture_without_the_needle() { + Captured("harmless startup line".into()).assert_not_contains("secret"); + } + + #[test] + fn a_panicked_capture_clears_the_slot() { + let caught = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| { + let _ = capture_logs(|| { + tracing::info!("residue-that-must-not-leak"); + panic!("intentional capture panic"); + }); + })); + assert!(caught.is_err(), "the inner f must panic"); + CAPTURE.with(|slot| { + assert!( + slot.borrow().is_none(), + "a panicked f must leave the capture slot empty" + ); + }); + let (_, logs) = capture_logs(probe); + assert_logged(&logs, PROBE); + logs.assert_not_contains("residue-that-must-not-leak"); } }