Skip to main content

max / makenotwork

Fix the flaky csp_report default-filter test The test installed its own scoped subscriber and read a buffer it owned, but callsite interest is cached process-wide: the two tests that call report_csp_violation reach the same warn! callsite with nothing installed, so whichever ran first could cache the interest as never and the capturing test saw an empty buffer. Install one subscriber for the whole lib test binary, under DEFAULT_LOG_FILTER, writing to a per-thread sink a Capture guard opts into. The assertion is unchanged. 20 consecutive cargo test --lib runs green.
Co-Authored-By
Claude Opus 5 (1M context) <noreply@anthropic.com>
Author: Max Johnson <me@maxj.phd> · 2026-08-25 22:40 UTC
Signed with PGP, not checked
Commit: f1190b1a85442197065deab250e7834bc3b14ecc
Parent: 141ee29
3 files changed, +122 insertions, -41 deletions
M server/src/lib.rs +5
@@ -82,6 +82,11 @@
82 82 #[cfg(test)]
83 83 mod deploy_lint;
84 84
85 + // Test-only tracing capture. Shared, because callsite interest is a global
86 + // cache and a per-test subscriber makes it depend on test order.
87 + #[cfg(test)]
88 + mod test_tracing;
89 +
85 90 use axum::{Router, extract::FromRef, http::HeaderValue, middleware};
86 91 use std::time::Instant;
87 92 use tower_http::limit::RequestBodyLimitLayer;
M server/src/routes/api/csp_report.rs +13 -41
@@ -156,50 +156,22 @@
156 156 /// what happened in production: `RUST_LOG` is unset, the default filter
157 157 /// named only the crate path, and `csp_violation` matched no directive, so
158 158 /// the deployed control discarded every report it accepted.
159 - #[tokio::test]
160 - async fn default_filter_actually_records_a_violation() {
161 - use std::io::Write;
162 - use std::sync::{Arc, Mutex};
163 - use tracing_subscriber::layer::SubscriberExt;
164 -
165 - #[derive(Clone)]
166 - struct Buffer(Arc<Mutex<Vec<u8>>>);
167 - impl Write for Buffer {
168 - fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
169 - self.0.lock().unwrap().extend_from_slice(buf);
170 - Ok(buf.len())
171 - }
172 - fn flush(&mut self) -> std::io::Result<()> {
173 - Ok(())
174 - }
175 - }
176 - impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for Buffer {
177 - type Writer = Self;
178 - fn make_writer(&'a self) -> Self::Writer {
179 - self.clone()
180 - }
181 - }
182 -
183 - let buffer = Buffer(Arc::new(Mutex::new(Vec::new())));
184 - let subscriber = tracing_subscriber::registry()
185 - .with(tracing_subscriber::EnvFilter::new(
186 - crate::DEFAULT_LOG_FILTER,
187 - ))
188 - .with(
189 - tracing_subscriber::fmt::layer()
190 - .with_ansi(false)
191 - .with_writer(buffer.clone()),
192 - );
159 + #[test]
160 + fn default_filter_actually_records_a_violation() {
161 + // Capture through the shared subscriber rather than a scoped one: the
162 + // two tests above hit this same callsite without capturing, and
163 + // callsite interest is cached process-wide, so a per-test subscriber
164 + // made this assertion depend on which test ran first. See
165 + // `crate::test_tracing`.
166 + let capture = crate::test_tracing::Capture::start();
193 167
194 168 let body = br#"{"csp-report":{"document-uri":"https://makenot.work/","violated-directive":"style-src","blocked-uri":"inline"}}"#;
195 - tracing::subscriber::with_default(subscriber, || {
196 - log_violation(
197 - &serde_json::from_slice::<Value>(body).unwrap()["csp-report"],
198 - "report-uri",
199 - );
200 - });
169 + log_violation(
170 + &serde_json::from_slice::<Value>(body).unwrap()["csp-report"],
171 + "report-uri",
172 + );
201 173
202 - let logged = String::from_utf8(buffer.0.lock().unwrap().clone()).unwrap();
174 + let logged = capture.logged();
203 175 assert!(
204 176 logged.contains("CSP violation reported"),
205 177 "the default filter dropped the violation; nothing would reach prod logs. got: {logged:?}"
A server/src/test_tracing.rs +104
@@ -1,0 +1,104 @@
1 + //! Test-only tracing capture, installed once for the whole lib test binary.
2 + //!
3 + //! # Why a global subscriber and not a scoped one
4 + //!
5 + //! `tracing` caches callsite interest globally. The first evaluation of a
6 + //! callsite decides whether the macro even runs, and with no subscriber
7 + //! installed that answer is "never". Two of the `csp_report` tests reach
8 + //! `log_violation`'s `warn!` callsite without capturing anything, so if either
9 + //! of them got there first the capturing test's event was discarded before any
10 + //! subscriber saw it. `set_global_default` rebuilds the cache, so installing
11 + //! one subscriber up front makes the cached answer a property of the filter
12 + //! rather than of which test the harness happened to schedule first.
13 + //!
14 + //! The filter is [`crate::DEFAULT_LOG_FILTER`] on purpose: what the capturing
15 + //! test asserts is that production's own filter lets a CSP violation through.
16 + //!
17 + //! # What it captures
18 + //!
19 + //! Events emitted **on the thread holding the guard**. Every other thread's
20 + //! events go to a sink, so a test that captures nothing stays silent and two
21 + //! tests capturing at once cannot read each other's output. A test whose events
22 + //! are emitted from a spawned thread or a multi-thread runtime worker will not
23 + //! see them here.
24 +
25 + use std::cell::RefCell;
26 + use std::io::Write;
27 + use std::sync::{Arc, Mutex, Once};
28 +
29 + thread_local! {
30 + /// Where this thread's events go, when it is capturing.
31 + static SINK: RefCell<Option<Arc<Mutex<Vec<u8>>>>> = const { RefCell::new(None) };
32 + }
33 +
34 + /// Writer handed to the `fmt` layer: routes each line to the emitting thread's
35 + /// buffer, or drops it when that thread is not capturing.
36 + #[derive(Clone)]
37 + struct ThreadSink;
38 +
39 + impl Write for ThreadSink {
40 + fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
41 + SINK.with(|sink| {
42 + if let Some(buffer) = sink.borrow().as_ref() {
43 + buffer.lock().unwrap().extend_from_slice(buf);
44 + }
45 + });
46 + Ok(buf.len())
47 + }
48 +
49 + fn flush(&mut self) -> std::io::Result<()> {
50 + Ok(())
51 + }
52 + }
53 +
54 + impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for ThreadSink {
55 + type Writer = Self;
56 + fn make_writer(&'a self) -> Self::Writer {
57 + Self
58 + }
59 + }
60 +
61 + /// Records this thread's tracing output for as long as it is held.
62 + pub(crate) struct Capture(Arc<Mutex<Vec<u8>>>);
63 +
64 + impl Capture {
65 + /// Begin capturing on the current thread, installing the shared subscriber
66 + /// if this is the first call.
67 + pub(crate) fn start() -> Self {
68 + install();
69 + let buffer = Arc::new(Mutex::new(Vec::new()));
70 + SINK.with(|sink| *sink.borrow_mut() = Some(Arc::clone(&buffer)));
71 + Self(buffer)
72 + }
73 +
74 + /// Everything this thread has emitted since the guard was taken.
75 + pub(crate) fn logged(&self) -> String {
76 + String::from_utf8(self.0.lock().unwrap().clone()).expect("fmt layer writes utf-8")
77 + }
78 + }
79 +
80 + impl Drop for Capture {
81 + fn drop(&mut self) {
82 + SINK.with(|sink| *sink.borrow_mut() = None);
83 + }
84 + }
85 +
86 + fn install() {
87 + static ONCE: Once = Once::new();
88 + ONCE.call_once(|| {
89 + use tracing_subscriber::layer::SubscriberExt;
90 +
91 + let subscriber = tracing_subscriber::registry()
92 + .with(tracing_subscriber::EnvFilter::new(
93 + crate::DEFAULT_LOG_FILTER,
94 + ))
95 + .with(
96 + tracing_subscriber::fmt::layer()
97 + .with_ansi(false)
98 + .with_writer(ThreadSink),
99 + );
100 +
101 + tracing::subscriber::set_global_default(subscriber)
102 + .expect("nothing else installs a global subscriber in the test binary");
103 + });
104 + }