crates/gunnar-cli/tests/common/capture.rs
//! **A `tracing` capture that can see spans**, not just events.
//!
//! # Why this is not `tracing_subscriber::fmt` with a `Vec<u8>` writer
//!
//! The claim being tested is *"every line emitted under a connection is
//! attributable without the call site repeating the fields"*. A capture that
//! only saw event fields could not tell a line that inherited `principal` from
//! its span from a line that stated `principal` itself, which is the exact
//! difference between the fix and the thing it replaced. So this layer keeps
//! each span's fields in that span's extensions, updates them when
//! [`tracing::Span::record`] fills an `Empty` in (`principal` and `repo` are
//! both recorded *after* the span is created), and attaches the whole inherited
//! set to every event.
//!
//! # Why a global subscriber
//!
//! `tracing::subscriber::with_default` is **thread-local**, and gunnar serves
//! every transfer on a spawned task and a blocking thread. A thread-local
//! subscriber would capture the test's own lines and none of the server's,
//! which would pass while seeing nothing (the vacuous-green trap). Each
//! Rust integration-test file is its own process, so a global subscriber
//! installed once per file is safe.
#![allow(dead_code)]
use std::collections::BTreeMap;
use std::sync::{Arc, Mutex, OnceLock};
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::registry::LookupSpan;
use tracing_subscriber::Layer;
/// One captured event: what it said, and everything it inherited.
#[derive(Clone, Debug)]
pub struct Line {
/// The `tracing` target: `gunnar::git`, `gunnar::ssh`, …
pub target: String,
/// Its level, lowercased.
pub level: String,
/// The `message` field.
pub message: String,
/// Fields stated on the event itself.
pub fields: BTreeMap<String, String>,
/// Fields inherited from the enclosing spans, root first. **This is the
/// property under test**: `conn`, `principal` and `repo` must be here on a
/// transfer's lines without the call site having written them.
pub inherited: BTreeMap<String, String>,
/// The span names enclosing this event, root first.
pub spans: Vec<String>,
}
impl Line {
/// A field, whether stated on the event or inherited from a span.
pub fn get(&self, key: &str) -> Option<&str> {
self.fields
.get(key)
.or_else(|| self.inherited.get(key))
.map(String::as_str)
}
/// A field that must have come from a **span**, not from the event.
pub fn inherited(&self, key: &str) -> Option<&str> {
self.inherited.get(key).map(String::as_str)
}
}
/// Everything captured since the subscriber was installed.
#[derive(Clone, Default)]
pub struct Captured(Arc<Mutex<Vec<Line>>>);
impl Captured {
/// Every line, in order.
pub fn lines(&self) -> Vec<Line> {
self.0.lock().expect("the capture lock").clone()
}
/// Lines emitted after `mark`, so one test does not read another's output.
/// The test binary is one process and they share the subscriber.
pub fn since(&self, mark: usize) -> Vec<Line> {
self.0.lock().expect("the capture lock")[mark..].to_vec()
}
/// Lines emitted after `mark`, once `done` holds for them, or whatever is there
/// when `within` runs out (the caller's asserts then name what is missing).
///
/// For a line the server writes AFTER the client already has its answer: an LFS
/// download logs `http.lfs.download.served` once the last byte is written, and with
/// `Content-Length` the client can read to the end before that line exists. Reading
/// the capture at once is a race the test loses under load (GUN-REL 2026-11-03).
#[allow(dead_code)] // each test binary that links `common` uses its own share of it
pub fn since_when(
&self,
mark: usize,
within: std::time::Duration,
done: impl Fn(&[Line]) -> bool,
) -> Vec<Line> {
let until = std::time::Instant::now() + within;
loop {
let lines = self.since(mark);
if done(&lines) || std::time::Instant::now() >= until {
return lines;
}
std::thread::sleep(std::time::Duration::from_millis(20));
}
}
/// How many lines have been captured so far.
pub fn mark(&self) -> usize {
self.0.lock().expect("the capture lock").len()
}
}
#[derive(Default)]
struct SpanFields(BTreeMap<String, String>);
struct Visitor<'a>(&'a mut BTreeMap<String, String>);
impl tracing::field::Visit for Visitor<'_> {
fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
// `%x` arrives here too, wrapped so `Debug` prints the `Display` form
// without quotes, which is why this is not `{value:?}` of a string.
self.0.insert(field.name().to_owned(), format!("{value:?}"));
}
fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
self.0.insert(field.name().to_owned(), value.to_owned());
}
}
struct CaptureLayer(Captured);
impl<S> Layer<S> for CaptureLayer
where
S: tracing::Subscriber + for<'a> LookupSpan<'a>,
{
fn on_new_span(
&self,
attrs: &tracing::span::Attributes<'_>,
id: &tracing::Id,
ctx: tracing_subscriber::layer::Context<'_, S>,
) {
let Some(span) = ctx.span(id) else { return };
let mut fields = BTreeMap::new();
attrs.record(&mut Visitor(&mut fields));
span.extensions_mut().insert(SpanFields(fields));
}
fn on_record(
&self,
id: &tracing::Id,
values: &tracing::span::Record<'_>,
ctx: tracing_subscriber::layer::Context<'_, S>,
) {
// `principal` and `repo` are declared `Empty` and filled in here. A
// capture that ignored this callback would report the connection span
// as anonymous forever.
let Some(span) = ctx.span(id) else { return };
let mut extensions = span.extensions_mut();
if let Some(SpanFields(fields)) = extensions.get_mut::<SpanFields>() {
values.record(&mut Visitor(fields));
}
}
fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
let mut fields = BTreeMap::new();
event.record(&mut Visitor(&mut fields));
let message = fields.remove("message").unwrap_or_default();
let mut inherited = BTreeMap::new();
let mut spans = Vec::new();
if let Some(scope) = ctx.event_scope(event) {
for span in scope.from_root() {
spans.push(span.name().to_owned());
if let Some(SpanFields(f)) = span.extensions().get::<SpanFields>() {
for (key, value) in f {
inherited.insert(key.clone(), value.clone());
}
}
}
}
self.0 .0.lock().expect("the capture lock").push(Line {
target: event.metadata().target().to_owned(),
level: event.metadata().level().to_string().to_lowercase(),
message,
fields,
inherited,
spans,
});
}
}
/// Install the capture **behind a real `EnvFilter`**, once.
///
/// The same layer as [`install`], with the filter in front of it, so a test can
/// ask the question a documented `RUST_LOG` string actually raises: *does this
/// filter select the lines the documentation says it does?* Reading the string,
/// or checking that the source contains a target literal, cannot answer it —
/// that is precisely how `"gunnar.lfs"` survived (see
/// `gunnar_core::observe::TARGET_LFS`).
///
/// A separate `OnceLock` from [`install`]'s: both call `set_global_default`, so
/// one test binary uses one or the other. Each integration-test file is its own
/// process, so that is a per-file choice and not a conflict.
pub fn install_filtered(filter: &str) -> Captured {
static CAPTURED: OnceLock<Captured> = OnceLock::new();
CAPTURED
.get_or_init(|| {
let captured = Captured::default();
let subscriber = tracing_subscriber::registry()
.with(tracing_subscriber::EnvFilter::new(filter))
.with(CaptureLayer(captured.clone()));
tracing::subscriber::set_global_default(subscriber)
.expect("no other global subscriber in this test binary");
captured
})
.clone()
}
/// Install the capture as this test process's global subscriber, once.
///
/// Returns the same [`Captured`] every time, so tests in one binary share one
/// buffer and read their own slice of it with [`Captured::mark`].
pub fn install() -> Captured {
static CAPTURED: OnceLock<Captured> = OnceLock::new();
CAPTURED
.get_or_init(|| {
let captured = Captured::default();
let subscriber = tracing_subscriber::registry().with(CaptureLayer(captured.clone()));
tracing::subscriber::set_global_default(subscriber)
.expect("no other global subscriber in this test binary");
captured
})
.clone()
}