crates/gunnar-cli/tests/observability.rs
#![cfg(feature = "server")]
//! **What an operator can see, asserted against a real clone.**
//!
//! Every test here drives the **stock `git` binary** over a **real SSH
//! connection** into a **real `gunnar serve`**, and then reads what the server
//! emitted. Nothing is stubbed, and in particular nothing here asserts that
//! gunnar *can* log. It asserts that a specific line, with specific fields,
//! came out of a specific operation.
//!
//! # Why instrumentation needs harder tests than most code
//!
//! Nothing fails when logging stops. A test that installed a subscriber and
//! asserted "no error" would pass against a server that emitted absolutely
//! nothing, which is precisely the state this suite exists to close. So:
//!
//! * every assertion names a **field** and a **value**, not a substring of
//! prose;
//! * the connection fields are asserted as **inherited from the span**
//! ([`Line::inherited`]), so a future call site that goes back to repeating
//! `principal = …` by hand does not satisfy them;
//! * the counters are read **before and after** and the delta asserted, because
//! a counter that merely exists is not a counter that moves;
//! * [`info_is_a_usable_production_default`] asserts the essential lines are at
//! `info` or above, so nothing important can quietly sink to `debug`;
//! * and the levels, the targets and the absence assertions are all checked
//! against a capture that is proved non-blind in the same test that uses it.
//!
//! # Seen red
//!
//! Recorded because a green assertion that has never failed is worth nothing.
//! With `span.record("principal", …)` deleted from `gunnar-ssh`'s
//! `auth_publickey`, `a_real_clone_emits_a_connection_span_carrying_the_
//! principal_and_the_repository` fails with *"the connection span does not
//! carry the principal"*, and only that test fails, so it is pinned to the
//! emission and not to the clone.
mod common;
use std::collections::BTreeSet;
use std::path::Path;
use std::process::Command;
use common::capture::{self, Line};
use common::{local_repo, tools_present, Harness};
use gunnar_core::{HashKind, RepoRef};
/// The lines one repository's traffic produced, narrowed so tests running in
/// parallel in the same process cannot read each other's output.
///
/// Narrowed by **connection id**, not by the `repo` field: the repository is
/// only known from `exec_request` on, so filtering on `repo` alone would drop
/// `ssh.auth.accepted`, which is the first line of the connection and the one
/// that names the principal. The repository picks the connections out; the
/// connections then pick every line, from the handshake on.
fn for_repo(lines: &[Line], repo: &str) -> Vec<Line> {
let conns: BTreeSet<&str> = lines
.iter()
.filter(|line| line.get("repo") == Some(repo))
.filter_map(|line| line.inherited.get("conn").map(String::as_str))
.collect();
assert!(
!conns.is_empty(),
"no connection ever named {repo}; either nothing was served or the connection span \
carries no id:\n{}",
render(lines)
);
lines
.iter()
.filter(|line| {
line.inherited
.get("conn")
.is_some_and(|conn| conns.contains(conn.as_str()))
})
.cloned()
.collect()
}
/// The one line with this `event` field, or a failure that prints what *was*
/// captured, because an assertion whose message is only "false" costs an hour.
fn one<'a>(lines: &'a [Line], event: &str) -> &'a Line {
let found: Vec<&Line> = lines
.iter()
.filter(|line| line.get("event") == Some(event))
.collect();
assert_eq!(
found.len(),
1,
"expected exactly one `{event}` line, found {}; captured:\n{}",
found.len(),
render(lines)
);
found[0]
}
fn render(lines: &[Line]) -> String {
lines
.iter()
.map(|line| {
format!(
" [{}] {} {:?} spans={:?} fields={:?} inherited={:?}",
line.level, line.target, line.message, line.spans, line.fields, line.inherited
)
})
.collect::<Vec<_>>()
.join("\n")
}
/// `git`, with a key of the caller's choosing rather than the harness's.
fn git_with_key(harness: &Harness, key: &Path, cwd: &Path, args: &[&str]) -> bool {
Command::new("git")
.current_dir(cwd)
.env(
"GIT_SSH_COMMAND",
format!(
"ssh -i {} -o IdentitiesOnly=yes -o IdentityAgent=none \
-o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null \
-o BatchMode=yes -o LogLevel=ERROR",
key.display()
),
)
.env("GIT_TERMINAL_PROMPT", "0")
.env("GIT_CONFIG_NOSYSTEM", "1")
.env("HOME", harness.dir.path())
.args(args)
.output()
.expect("git is on PATH")
.status
.success()
}
// ───────────────────────────────────────────────────────────────────────────
// The connection span
// ───────────────────────────────────────────────────────────────────────────
#[test]
fn a_real_clone_emits_a_connection_span_carrying_the_principal_and_the_repository() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "spanned", HashKind::Sha1);
let url = harness.url("team", "spanned");
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "observable\n");
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("push");
let mark = captured.mark();
let back = harness.dir.path().join("back");
harness
.git(
harness.dir.path(),
&["clone", "--quiet", &url, back.to_str().unwrap()],
)
.expect_ok("clone");
let lines = for_repo(&captured.since(mark), "team/spanned");
assert!(
!lines.is_empty(),
"the clone emitted NOTHING attributable to team/spanned. Either the capture is blind \
or the server is silent, and either way every assertion below would be vacuous"
);
// ── the applied-output line, and what it must carry ────────────────────
let served = one(&lines, "git.upload_pack.served");
assert_eq!(served.target, "gunnar::git");
assert_eq!(served.level, "info");
// **Which path answered the fetch.** `Selection::answered_from_bitmap` has
// existed so that a guard could assert exactly this, and until 2026-08-31
// NOTHING read it — not a log line, not a metric, not a test; its only
// reader in the whole constellation was an example binary.
//
// The cost of that was measured, not imagined: `--fetch-budget` charged the
// ids a WALKER holds, and on the store the appliance actually runs there is
// no walker because the reachability index answers whole — so the control
// was compared against nothing, behind a red test that three separate
// reviews each read as a policy question and stepped around.
//
// This asserts the field is THERE and is a boolean. It deliberately does
// not assert WHICH path this fixture takes: that depends on whether the
// store under test carries an index, and a test that guessed would be
// asserting the fixture rather than the server. What must never be true
// again is that nobody can tell.
let from_index = served.get("from_index").unwrap_or_else(|| {
panic!(
"git.upload_pack.served does not say which path answered; that is the blind spot \
that let --fetch-budget sit inert:\n{}",
render(&lines)
)
});
assert!(
from_index == "true" || from_index == "false",
"from_index must be a boolean, not {from_index:?}"
);
// Inherited from `ssh.connection`, NOT restated by the call site. This is
// the whole claim of the fix: `crates/gunnar-cli/src/server/transport.rs`
// names neither the principal nor the repository on this line.
assert_eq!(
served.inherited("principal"),
Some("tester"),
"the connection span does not carry the principal:\n{}",
render(&lines)
);
assert_eq!(
served.inherited("repo"),
Some("team/spanned"),
"the connection span does not carry the repository:\n{}",
render(&lines)
);
let conn = served
.inherited("conn")
.expect("the connection span must carry a request id");
assert_eq!(conn.len(), 16, "the request id is not the fixed-width form");
assert!(
conn.chars().all(|c| c.is_ascii_hexdigit()),
"the request id `{conn}` is not greppable"
);
assert!(
served
.inherited("peer")
.is_some_and(|peer| peer.starts_with("127.0.0.1:")),
"the connection span does not carry the peer address: {:?}",
served.inherited("peer")
);
// …and the span stack itself, so a future refactor that flattens the
// hierarchy is caught rather than silently losing the inheritance.
assert_eq!(
served.spans,
vec![
"ssh.connection".to_owned(),
"git.transfer".to_owned(),
"git.upload_pack".to_owned()
],
"the span hierarchy is not connection → transfer → operation"
);
// ── the applied outputs, which are what make the line worth reading ────
assert_eq!(
served.get("objects").and_then(|v| v.parse::<u64>().ok()),
Some(3),
"the served line does not report the objects actually sent (one commit \
is a commit, a tree and a blob):\n{}",
render(&lines)
);
let bytes_out = served
.get("bytes_out")
.and_then(|v| v.parse::<u64>().ok())
.expect("the served line must report bytes out");
assert!(
bytes_out > 100,
"bytes_out is {bytes_out}, which is not a packfile. The byte counter is not wired to \
the wire"
);
assert!(
served.get("elapsed_ms").is_some(),
"the served line has no duration, so `why was that clone slow` is still unanswerable"
);
assert_eq!(
served.get("protocol"),
Some("2"),
"the protocol must be what was SPOKEN, taken from the session summary"
);
assert!(served.get("rounds").is_some(), "no negotiation rounds");
// ── attributability: EVERY line under this connection carries the id ───
let under_connection: Vec<&Line> = lines
.iter()
.filter(|line| line.spans.first().map(String::as_str) == Some("ssh.connection"))
.collect();
assert!(
under_connection.len() >= 3,
"only {} lines were emitted under the connection span; the transfer is not instrumented",
under_connection.len()
);
for line in &under_connection {
assert_eq!(
line.inherited("conn"),
Some(conn),
"a line under the connection span is not attributable to it: {line:?}"
);
}
// ── the transfer's own lifecycle, with its own duration ────────────────
let finished = one(&lines, "git.transfer.finished");
assert_eq!(finished.get("status"), Some("0"), "a clean clone exits 0");
assert!(finished.get("elapsed_ms").is_some());
}
// ───────────────────────────────────────────────────────────────────────────
// Refusals
// ───────────────────────────────────────────────────────────────────────────
#[test]
fn a_refused_connection_names_a_reason_and_moves_the_counter() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "refused", HashKind::Sha1);
// A real key that gunnar has never heard of.
let stranger = gunnar_core::mint_ed25519().expect("mint a stranger key");
let stranger_path = harness.dir.path().join("id_stranger");
std::fs::write(&stranger_path, &stranger).expect("write the stranger key");
#[cfg(unix)]
{
use std::os::unix::fs::PermissionsExt;
std::fs::set_permissions(&stranger_path, std::fs::Permissions::from_mode(0o600))
.expect("chmod");
}
let before = harness
.server
.as_ref()
.expect("the server is running")
.metrics();
let mark = captured.mark();
let ok = git_with_key(
&harness,
&stranger_path,
harness.dir.path(),
&[
"clone",
"--quiet",
&harness.url("team", "refused"),
harness.dir.path().join("nope").to_str().unwrap(),
],
);
assert!(!ok, "an unregistered key must not be able to clone");
let lines = captured.since(mark);
let refusals: Vec<&Line> = lines
.iter()
.filter(|line| line.get("event") == Some("ssh.auth.refused"))
.collect();
assert!(
!refusals.is_empty(),
"a refused connection produced no refusal line at all:\n{}",
render(&lines)
);
let refusal = refusals[0];
assert_eq!(refusal.target, "gunnar::ssh");
assert_eq!(
refusal.level, "warn",
"a refused key must be at `warn`. An operator greps for refusals, and `debug` hides \
them behind a flag nobody sets in production"
);
assert_eq!(
refusal.get("reason"),
Some("unknown-key"),
"the refusal does not say WHY it refused; `unknown key` and `the identity table could \
not be read` are different incidents:\n{}",
render(&lines)
);
assert!(
refusal
.get("fingerprint")
.is_some_and(|f| f.starts_with("SHA256:")),
"the refusal does not name the key that was offered, so nobody can tell the user which \
key to register: {:?}",
refusal.get("fingerprint")
);
assert!(
refusal.inherited("conn").is_some(),
"even a refusal is emitted under the connection span, or the two lines of a failed \
handshake cannot be tied together"
);
assert_eq!(
refusal.inherited("principal"),
None,
"a refused key names NO principal. A refusal that named one would put a connection \
that never authenticated into an identity's history"
);
// ── the counter, before and after ──────────────────────────────────────
let after = harness
.server
.as_ref()
.expect("the server is running")
.metrics();
assert!(
after.connections_refused > before.connections_refused,
"connections_refused did not move: {} → {}",
before.connections_refused,
after.connections_refused
);
assert_eq!(
after.auth_faults, before.auth_faults,
"an unknown key is not a storage FAULT, and counting it as one would send an operator \
to look at the disk"
);
assert_eq!(
after.transfers_started, before.transfers_started,
"a connection that never authenticated must not count as a transfer"
);
}
#[test]
fn a_refused_push_names_the_gate_and_the_reference() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "gated", HashKind::Sha1);
let config = gunnar_policy::PolicyConfig {
protection: vec![gunnar_policy::ProtectionRule::protect("refs/heads/main").unwrap()],
..Default::default()
};
let repo = harness
.stores
.catalog()
.open(&RepoRef::new("team", "gated").unwrap())
.unwrap();
let git_dir = harness
.stores
.repo_store(&repo)
.unwrap()
.git_dir()
.to_path_buf();
std::fs::write(
git_dir.join(gunnar_cli::server::transport::POLICY_FILE),
config.to_json().unwrap(),
)
.expect("write the policy document");
let url = harness.url("team", "gated");
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "one\n");
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("creating the protected branch");
// Rewrite history, so branch protection has something to refuse. The
// second commit must be PUSHED first; without that, the "force" push is a
// plain fast-forward and the gate has nothing to say.
std::fs::write(work.join("hello.txt"), "two\n").unwrap();
harness.git(&work, &["add", "hello.txt"]).expect_ok("add");
harness
.git(&work, &["commit", "--quiet", "-m", "second"])
.expect_ok("commit");
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("a fast-forward is allowed under this rule");
harness
.git(&work, &["reset", "--hard", "HEAD~1"])
.expect_ok("reset");
std::fs::write(work.join("hello.txt"), "divergent\n").unwrap();
harness.git(&work, &["add", "hello.txt"]).expect_ok("add");
harness
.git(&work, &["commit", "--quiet", "-m", "divergent"])
.expect_ok("commit");
let before = harness
.server
.as_ref()
.expect("the server is running")
.metrics();
let mark = captured.mark();
harness
.git(&work, &["push", "--force", &url, "HEAD:refs/heads/main"])
.expect_failure("a force-push onto a protected branch");
let lines = for_repo(&captured.since(mark), "team/gated");
let refused = one(&lines, "policy.gate.refused");
assert_eq!(refused.target, "gunnar::policy");
assert_eq!(
refused.level, "warn",
"a gate refusal is the line an operator greps for"
);
assert_eq!(
refused.get("gate"),
Some("branch-protection"),
"the refusal does not NAME the gate that made it:\n{}",
render(&lines)
);
assert_eq!(
refused.inherited("ref_name"),
Some("refs/heads/main"),
"the refusal does not name the reference it refused:\n{}",
render(&lines)
);
assert!(
refused
.get("reason")
.is_some_and(|reason| !reason.is_empty()),
"the refusal carries no reason"
);
assert!(
refused.inherited("conn").is_some() && refused.inherited("principal") == Some("tester"),
"the gate refusal is not attributable to the connection that caused it: {refused:?}"
);
// The reference-level line agrees with the gate about who said no. Two
// places that could disagree about the same refusal is exactly what the event
// stream's
// empty `gate` field used to be.
let ref_rejected = one(&lines, "git.ref.rejected");
assert_eq!(
ref_rejected.get("gate"),
Some("branch-protection"),
"the ref-level line does not carry the gate the policy line named"
);
let after = harness
.server
.as_ref()
.expect("the server is running")
.metrics();
assert!(
after.gate_refusals > before.gate_refusals,
"gate_refusals did not move: {} → {}",
before.gate_refusals,
after.gate_refusals
);
assert!(
after.pushes_rejected > before.pushes_rejected,
"pushes_rejected did not move: {} → {}",
before.pushes_rejected,
after.pushes_rejected
);
assert_eq!(
after.pushes_accepted, before.pushes_accepted,
"a refused push must NOT also be counted as accepted"
);
assert!(
after.refs_updated == before.refs_updated,
"no reference moved, so refs_updated must not have"
);
}
// ───────────────────────────────────────────────────────────────────────────
// The counters
// ───────────────────────────────────────────────────────────────────────────
#[test]
fn a_real_push_and_clone_move_the_counters() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let _captured = capture::install();
let harness = Harness::start("team", "counted", HashKind::Sha1);
let server = harness.server.as_ref().expect("the server is running");
let before = server.metrics();
assert_eq!(
before.transfers_started, 0,
"a server that has served nothing must read zero, or every delta below is measured \
against noise"
);
let url = harness.url("team", "counted");
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "counted\n");
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("push");
let back = harness.dir.path().join("back");
harness
.git(
harness.dir.path(),
&["clone", "--quiet", &url, back.to_str().unwrap()],
)
.expect_ok("clone");
let after = server.metrics();
// Deltas, field by field. `assert!(after != before)` would pass on any one
// counter moving and tell nobody which.
assert!(
after.connections_accepted >= 2,
"a push and a clone are at least two authenticated connections, got {}",
after.connections_accepted
);
assert_eq!(
after.connections_refused, 0,
"nothing was refused, so the refusal counter must NOT have moved. A counter that only \
ever goes up is not measuring anything"
);
assert!(
after.transfers_started >= 2,
"transfers_started is {}",
after.transfers_started
);
assert_eq!(
after.transfers_in_flight, 0,
"the in-flight gauge did not come back down; a leaked gauge makes an idle server read \
as saturated forever"
);
assert_eq!(after.transfers_failed, 0);
assert_eq!(
after.pushes_accepted, 1,
"exactly one push landed, and it landed"
);
assert_eq!(after.pushes_rejected, 0);
assert_eq!(
after.refs_updated, 1,
"one reference moved: refs/heads/main"
);
assert_eq!(after.refs_rejected, 0);
assert_eq!(
after.packs_served, 1,
"the clone was served exactly one packfile"
);
assert!(
after.objects_sent >= 3,
"a commit, a tree and a blob, at least: got {}",
after.objects_sent
);
assert!(
after.bytes_out > after.objects_sent,
"bytes_out ({}) is not plausibly a packfile. It must be MEASURED at the wire, not \
derived from an object count",
after.bytes_out
);
assert!(
after.bytes_in > 0,
"the push sent a pack; bytes_in must have moved"
);
assert_eq!(after.auth_faults, 0);
assert_eq!(after.exec_refused, 0);
assert_eq!(after.gate_refusals, 0, "no gates are configured here");
}
// ───────────────────────────────────────────────────────────────────────────
// The numbers on the push line
// ───────────────────────────────────────────────────────────────────────────
/// The bytes the STORE holds, on the engine that ships.
///
/// This read `objects/pack/*.pack` until 2026-08-30, which is a directory the
/// znippy engine never creates: it appends the received pack VERBATIM into one
/// archive and writes no packfile (`IndexedPack::data_path` is `None`). So the
/// fixture measured 0 on every push and the test's own "would be vacuous" guard
/// fired — the premise was wrong, not the server.
///
/// A packfile engine's comparable number is the sum of its `objects/pack/*.pack`
/// files, and it is the SAME number: `bench/src/store_bytes.rs` measured both
/// shapes at 1 246 466 bytes for the same repository. No arm of this suite
/// starts a packfile engine — the assertions below (`pack == wire`, and the
/// pack fitting inside the archive) are written for the verbatim-append store —
/// so this measures the one shape that can occur here rather than branching on
/// which of the two is non-empty.
fn stored_archive_bytes(git_dir: &Path) -> u64 {
std::fs::metadata(git_dir.join("gunnar-git.znippy").join("objects.pack"))
.map(|meta| meta.len())
.unwrap_or(0)
}
/// **`pack_bytes` is the file on disk, and a deletion's zero is a measurement.**
///
/// The field used to be `unwrap_or(0)` over three different absences, so a
/// failed `stat` and a push that carried nothing printed the same line, and
/// nothing anywhere asserted the number at all. Both arms are checked here
/// against the filesystem, because a log field that is never compared to the
/// thing it describes is the identity-value trap in a different coat.
///
/// Seen red: with `pack_bytes` forced to `Some(0)` in
/// `transport.rs::measured_pack_bytes`, the first assertion fails with the
/// on-disk size in the message and the second still passes — so the two arms
/// are pinned to different facts and not to each other.
#[test]
fn the_push_line_reports_the_pack_that_landed_and_a_deletion_reports_a_real_zero() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "weighed", HashKind::Sha1);
let url = harness.url("team", "weighed");
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "weighed\n");
// ── a push that carries a pack ─────────────────────────────────────────
let mark = captured.mark();
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("push");
let lines = for_repo(&captured.since(mark), "team/weighed");
let served = one(&lines, "git.receive_pack.served");
let on_disk = stored_archive_bytes(&harness.git_dir("team", "weighed"));
assert!(
on_disk > 0,
"the fixture found no store at all, so the assertions below would be vacuous"
);
assert_eq!(
served.get("pack_bytes_unknown"),
None,
"a pack that was measured must carry no reason for not being measured. This is the \
field that said `pack … was indexed without a directory` on EVERY push into the \
engine gunnar ships, because the size was thrown away with the path it never had"
);
assert_eq!(
served.get("wire_bytes_unknown"),
None,
"the ingest counted the wire; nothing may claim it did not"
);
let pack: u64 = served
.get("pack_bytes")
.expect("the line must carry pack_bytes")
.parse()
.expect("pack_bytes is a number");
let wire: u64 = served
.get("wire_bytes")
.expect("the line must carry wire_bytes")
.parse()
.expect("wire_bytes is a number");
assert!(
wire > 0,
"a push that moved a reference sent bytes; wire_bytes read {wire}"
);
// **Two numbers produced by two crates, and on this engine they must
// agree.** `wire_bytes` is counted off the socket by `gunnar-wire`'s
// `Counting`; `pack_bytes` comes back from the store's own `PushReceipt`
// through `gunnar-server`. They are equal here for a stated reason and not
// by coincidence: the znippy store appends what it received verbatim, so
// nothing completes a thin pack at ingest and no byte is added. A packfile
// engine WOULD differ, which is why the reason is written down rather than
// the equality being assumed.
assert_eq!(
pack, wire,
"pack_bytes={pack} and wire_bytes={wire}. This engine stores the received pack verbatim, \
so they are the same bytes counted twice by two different crates; a divergence means \
one of the two is not measuring what it says"
);
// …and resolved to the store on disk. The pack was appended into the
// archive, so the archive is at least that big and the pack's own trailing
// checksum is inside it. A constant or a stale number fails both.
assert!(
pack <= on_disk,
"pack_bytes={pack} but the store holds only {on_disk} bytes; the pack was appended into \
it, so the first can never exceed the second"
);
// ── a push that carries none ───────────────────────────────────────────
//
// A deletion is the ONE case where zero is the right answer, and it has to
// stay distinguishable from the failures above: the number is present and
// zero, and no reason accompanies it.
let mark = captured.mark();
harness
.git(&work, &["push", &url, ":refs/heads/main"])
.expect_ok("delete refs/heads/main");
let lines = for_repo(&captured.since(mark), "team/weighed");
let served = one(&lines, "git.receive_pack.served");
assert_eq!(
served.get("pack_bytes"),
Some("0"),
"a deletions-only push carries no pack, and that is a MEASURED zero which must be \
printed rather than omitted"
);
assert_eq!(
served.get("pack_bytes_unknown"),
None,
"zero bytes is not an unknown"
);
assert_eq!(served.get("refs_ok"), Some("1"), "the deletion landed");
}
// ───────────────────────────────────────────────────────────────────────────
// The scheme itself
// ───────────────────────────────────────────────────────────────────────────
#[test]
fn info_is_a_usable_production_default() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "levels", HashKind::Sha1);
let url = harness.url("team", "levels");
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "levels\n");
let mark = captured.mark();
harness
.git(&work, &["push", &url, "HEAD:refs/heads/main"])
.expect_ok("push");
let back = harness.dir.path().join("back");
harness
.git(
harness.dir.path(),
&["clone", "--quiet", &url, back.to_str().unwrap()],
)
.expect_ok("clone");
let lines = for_repo(&captured.since(mark), "team/levels");
// The set an operator must get from a server running at the shipped
// default. Each of these sinking to `debug` would be invisible in
// production, which is how instrumentation rots.
for event in [
"ssh.auth.accepted",
"git.transfer.started",
"git.transfer.finished",
"git.upload_pack.served",
"git.receive_pack.served",
"git.ref.updated",
// ── the push's phases, not only its verdict ────────────────────────
//
// `git.receive_pack.served` is emitted when the push is over. Between
// the client's first byte and that line there are three phases that can
// each run for minutes on a large repository, and until this list grew
// they emitted **nothing**: the `linux.git` import (13 816 503 objects,
// 8 170 MB pack, 2 872 refs; 2026-08-05) wrote its pack and index in
// ~30 min and had still logged no line at 40 min, so a working import
// and a hang produced the identical empty log.
//
// Both halves of each phase are required. An exit-only line still
// leaves the minutes before it unattributed, which is the state that
// was unreadable; an entry-only line never says what the phase found.
"git.receive_pack.commands",
"git.receive_pack.receiving",
"git.receive_pack.indexed",
"git.receive_pack.checking",
"git.receive_pack.checked",
"git.receive_pack.updating",
"git.receive_pack.updated",
] {
let found: Vec<&Line> = lines
.iter()
.filter(|line| line.get("event") == Some(event))
.collect();
assert!(
!found.is_empty(),
"`{event}` was never emitted at all:\n{}",
render(&lines)
);
for line in found {
assert!(
matches!(line.level.as_str(), "info" | "warn" | "error"),
"`{event}` is emitted at `{}`, so it is invisible on a server running at the \
shipped `info` default",
line.level
);
}
}
// …and the target scheme holds. Two halves, and the second is the one that
// stops the scheme rotting:
let targets: BTreeSet<&str> = lines.iter().map(|line| line.target.as_str()).collect();
for target in &targets {
if target.starts_with("gunnar::") {
assert!(
gunnar_core::observe::TARGETS.contains(target),
"`{target}` looks like a declared target but is not in {:?}. A target invented \
at one call site is invisible to every filter written for the others",
gunnar_core::observe::TARGETS
);
}
}
assert!(
targets.contains("gunnar::ssh") && targets.contains("gunnar::git"),
"a push and a clone touched only {targets:?}"
);
// **The known remainder, pinned.** These crates' lines are still on the
// default module-path target. They INHERIT the connection span (the id, the
// principal and the repository are on them), but `RUST_LOG=gunnar::git=debug`
// does not select them. Listing them here means the gap cannot grow
// silently: a new module-path target anywhere in the serving path turns
// this red.
//
// `gunnar_pack::*` came off this list rather than gaining a third entry
// when the `copy` module arrived. All three of that crate's lines are on
// `gunnar_pack::GIT_TARGET` now. See the pin below, which is what stops
// the two spellings of `gunnar::git` drifting apart.
let undeclared: BTreeSet<&str> = targets
.iter()
.copied()
.filter(|target| !target.starts_with("gunnar::"))
.collect();
// `gunnar_wire::receive_pack` came off this list rather than staying on it:
// every line the push path emits is on `gunnar_wire::GIT_TARGET` now, so
// `RUST_LOG=warn,gunnar::git=info` — the quiet-production filter the module
// header documents — selects the phase log instead of dropping it. The
// fetch path's lines are still on the module-path default and are still
// pinned here.
// `gunnar_wire::upload_pack` came off this list on 2026-08-05, the same way
// `gunnar_pack::*` and `gunnar_wire::receive_pack` did before it. That
// crate's whole clone path emits ONE line, and it was on the module-path
// default: `RUST_LOG=gunnar::git=debug` selected the push path's seven
// phases and not a single thing a clone did. It is on
// `gunnar_wire::GIT_TARGET` now.
// `znippy_plugin_git::git_ops` joined 2026-09-08 with the per-object progress
// publish (`put_pack_observed`): the engine narrates the walk on its own
// module path, in a crate this repository does not own. Recorded here for
// the same reason `gunnar_store::repack` is — a quiet-production filter
// must know what it is silencing.
let known: BTreeSet<&str> = ["gunnar_store::repack", "znippy_plugin_git::git_ops"]
.into_iter()
.collect();
assert!(
undeclared.is_subset(&known),
"a NEW module-path target appeared in the serving path: {:?}. Every line gunnar owns \
belongs on a `gunnar::` target; the ones in `known` are the recorded remainder in \
crates this change does not own.",
undeclared.difference(&known).collect::<Vec<_>>()
);
}
#[test]
fn the_audit_target_is_the_same_string_in_both_crates() {
// `gunnar-grpc` deliberately has no `gunnar-core` edge (it is expressed in
// `gunnar-proto` terms), so `gunnar::audit` is the one constant stated
// twice. This crate links both, and is therefore the only place the two can
// be compared. Without this, a rename on one side would silently split the
// audit trail in half.
assert_eq!(
gunnar_core::observe::TARGET_AUDIT,
gunnar_grpc::AUDIT_TARGET,
"the audit target has drifted between gunnar-core and gunnar-grpc"
);
assert!(gunnar_core::observe::TARGETS.contains(&gunnar_grpc::AUDIT_TARGET));
}
#[test]
fn the_receive_pack_target_is_the_same_string_in_both_crates() {
// Third of the same shape, third for the same reason: `gunnar-wire` is
// plumbing under the no-OS rule and the crate layout, and has no `gunnar-core` edge — reaching one `&str`
// through it would put the identity table, the ACL and the path sandbox in
// the appliance's crate budget. So `gunnar::git` is stated twice and this
// crate, which links both, is the only place the two can be compared.
//
// Without this pin the push phase log goes back onto
// `gunnar_wire::receive_pack`, which no `gunnar::git` filter selects, and
// the fix for a silent forty-minute import would be silent again.
assert_eq!(
gunnar_core::observe::TARGET_GIT,
gunnar_wire::GIT_TARGET,
"the git transfer target has drifted between gunnar-core and gunnar-wire"
);
assert!(gunnar_core::observe::TARGETS.contains(&gunnar_wire::GIT_TARGET));
}
#[test]
fn the_pack_target_is_the_same_string_in_both_crates() {
// Same shape, same reason: `gunnar-pack` is plumbing on the server side of
// the dependency guard and has no `gunnar-core` edge, so `gunnar::git` is
// stated twice. This crate links both. Without this pin, a rename on either
// side would put the packfile lines back on a target no filter selects,
// which is precisely how they got onto the module-path default before.
assert_eq!(
gunnar_core::observe::TARGET_GIT,
gunnar_pack::GIT_TARGET,
"the git transfer target has drifted between gunnar-core and gunnar-pack"
);
assert!(gunnar_core::observe::TARGETS.contains(&gunnar_pack::GIT_TARGET));
}
#[test]
fn the_lfs_target_is_the_same_string_in_both_crates() {
// Same shape, same reason: `gunnar-lfs` has no `gunnar-core` edge.
//
// ⚠ This one is not a pin against future drift; it is a pin against a
// spelling that WAS wrong. `gunnar-lfs` emitted on `"gunnar.lfs"` — a dot
// instead of `::` — at five call sites, so `RUST_LOG=gunnar::lfs=debug`
// selected none of them and neither did any other documented filter. An
// LFS session's every refusal was written and unreadable.
assert_eq!(
gunnar_core::observe::TARGET_LFS,
gunnar_lfs::LFS_TARGET,
"the LFS target has drifted between gunnar-core and gunnar-lfs"
);
assert!(gunnar_core::observe::TARGETS.contains(&gunnar_lfs::LFS_TARGET));
}
/// **Every tracing target in the shipped source is one this server documents.**
///
/// The guard the other four in this file could not be. Each of them pins one
/// named constant against another named constant, and a call site that spells
/// its target inline passes through none of them:
/// `every_target_is_a_gunnar_sibling_and_the_list_is_complete` in `gunnar-core`
/// checks the members of `TARGETS` against each other and never looks at a
/// `tracing::` call at all.
///
/// So seventeen call sites sat on `"gunnar.lfs"` and `"gunnar.store"` — a dot,
/// not `::` — across `gunnar-lfs`, the old znippy engine crate, `gunnar-cli`'s znippy-engine
/// arm and `gunnar-znippy`, with five guards green above them. `RUST_LOG`
/// selected none of them by any filter this repository documents. They were
/// found by reading, which is not a method.
///
/// This reads the source of every shipped crate — `crates/*/src/**.rs`, the
/// same set `xtask`'s pack-pipeline guard scans — and requires every literal
/// tracing target beginning `gunnar` to be a member of
/// [`gunnar_core::observe::TARGETS`].
#[test]
fn every_tracing_target_in_the_shipped_source_is_one_of_ours() {
let root = std::path::Path::new(env!("CARGO_MANIFEST_DIR"))
.parent()
.and_then(|p| p.parent())
.expect("the workspace root is two levels above this crate")
.to_path_buf();
let crates = root.join("crates");
assert!(
crates.is_dir(),
"no crates/ directory at {}; this guard would sweep nothing and report clean",
crates.display()
);
let mut sources = Vec::new();
fn collect(dir: &std::path::Path, out: &mut Vec<std::path::PathBuf>) {
let Ok(entries) = std::fs::read_dir(dir) else {
return;
};
for entry in entries.flatten() {
let path = entry.path();
if path.is_dir() {
collect(&path, out);
} else if path.extension().and_then(|e| e.to_str()) == Some("rs") {
out.push(path);
}
}
}
for entry in std::fs::read_dir(&crates).expect("read crates/").flatten() {
collect(&entry.path().join("src"), &mut sources);
}
sources.sort();
// ── the anti-empty-sweep floor ─────────────────────────────────────────
//
// Zero findings over zero files is shaped exactly like a clean sweep. A
// path typo, a rename of `crates/`, or a `read_dir` that silently failed
// would all produce a confident pass, which is the failure mode this whole
// file exists to be about.
assert!(
sources.len() > 100,
"swept only {} source files; this guard is reading nothing",
sources.len()
);
let mut offenders: Vec<String> = Vec::new();
let mut seen = 0usize;
for path in &sources {
let Ok(text) = std::fs::read_to_string(path) else {
continue;
};
let rel = path
.strip_prefix(&root)
.unwrap_or(path)
.display()
.to_string();
for (number, line) in text.lines().enumerate() {
// `target: "…"` — the only way a tracing macro takes a literal
// target. A `target: SOME_CONST` is out of scope here on purpose:
// the constant is pinned by the four tests above, and following it
// would mean this test parsing Rust.
let Some(rest) = line.split("target: \"").nth(1) else {
continue;
};
let Some(target) = rest.split('"').next() else {
continue;
};
if !target.starts_with("gunnar") {
continue;
}
seen += 1;
if !gunnar_core::observe::TARGETS.contains(&target) {
offenders.push(format!("{rel}:{} target: {target:?}", number + 1));
}
}
}
// The same floor one level down: a scan that found no literal target at all
// proves nothing about the ones that exist.
assert!(
seen > 0,
"swept {} files and found no literal `target: \"gunnar…\"` anywhere, so the check \
below never ran",
sources.len()
);
assert!(
offenders.is_empty(),
"{} tracing call site(s) emit on a target NO documented RUST_LOG filter selects. \
`gunnar::` with two colons, and a member of gunnar_core::observe::TARGETS \
({:?}):\n {}",
offenders.len(),
gunnar_core::observe::TARGETS,
offenders.join("\n ")
);
}
/// A captured log must be **greppable**, and that is an assertion about the
/// real binary's real stderr, not about a builder call.
///
/// `tracing_subscriber::fmt` colours unconditionally by default: its ANSI
/// setting is `cfg!(feature = "ansi")` and is never conditioned on the writer.
/// The escapes wrap the *field names*, so a line captured to a file or a
/// journal reads `\x1b[3mbytes_out\x1b[0m\x1b[2m=\x1b[0m8170` and
/// `grep bytes_out=` matches nothing — a pipeline summing those matches
/// reports a confident **0**, which is shaped exactly like a clean result. The
/// Fet Kaos Monkey rig produced one on 2026-08-05.
///
/// # Why this runs the binary
///
/// `init_tracing` installs a process-global subscriber through `try_init`, so
/// it cannot be exercised in a test process that has already installed one —
/// and asserting that the builder was *told* `with_ansi(false)` would assert
/// the code back at itself. A child process with its stderr on a pipe is the
/// production case exactly: not a terminal, and captured by something that will
/// grep it.
#[test]
fn the_log_a_capture_sees_carries_no_terminal_escapes() {
let dir = tempfile::tempdir().expect("a scratch data root");
let out = std::process::Command::new(env!("CARGO_BIN_EXE_gunnar-cli"))
.arg("repo")
.arg("list")
.env("GUNNAR_DATA_ROOT", dir.path())
// Not inherited from the test runner, which may carry any filter.
.env("RUST_LOG", "info")
.output()
.expect("run the gunnar binary");
let stderr = String::from_utf8_lossy(&out.stderr);
// Non-vacuity first. An empty stderr has no escapes in it either, and a
// subcommand that logged nothing would pass this test having proven
// nothing. `repo list` on a fresh data root mints and seals a key and says
// so at `info`.
assert!(
stderr.contains("INFO"),
"the binary logged nothing at all, so this test asserts nothing:\n{stderr}"
);
assert!(
!stderr.contains('\u{1b}'),
"gunnar's log carries ANSI escapes when stderr is a pipe rather than a terminal, so \
every field name in a captured log is wrapped in them and no plain-text grep for one \
can ever match:\n{}",
stderr.escape_debug()
);
}
// ───────────────────────────────────────────────────────────────────────────
// The HTTP request span
// ───────────────────────────────────────────────────────────────────────────
/// **An HTTP transfer's own lines carry the request id the client was given.**
///
/// The header alone is not the fix. If `x-gunnar-request-id` went out and no
/// server line carried it, an operator would have a number and nothing to grep
/// for. The value is in the join, and the join is the part most likely to be
/// broken by construction: `spawn_transport` hands the transfer to a
/// `tokio::spawn`ed task, and a spawned task starts with **no span at all** —
/// the current span is thread-local and does not cross the spawn. So without
/// `.instrument(span)` the entire transfer, every line `gunnar-wire` and
/// `gunnar-cli`'s transport emit, falls outside `http.request`.
///
/// This asserts `git.upload_pack.served` — a line emitted three crates away,
/// inside `spawn_blocking` inside `tokio::spawn` — carries `req`, `principal`
/// and `repo` **inherited from the span** rather than restated at the call
/// site, which is the same claim
/// `a_real_clone_emits_a_connection_span_carrying_the_principal_and_the_repository`
/// makes for SSH.
///
/// Seen red: with `.instrument(span)` deleted from `spawn_transport`, the
/// transfer's lines carry no `req` at all and this fails with *"the served line
/// carries no req"*. With `span.record("principal", …)` deleted, only the
/// principal assertion fails.
#[cfg(feature = "http")]
#[test]
fn an_http_clone_puts_the_whole_transfer_under_one_request_id() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = common::Harness::start_with_options(
"team",
"correlated",
HashKind::Sha1,
common::HarnessOptions {
http: true,
visibility: gunnar_core::Visibility::Public,
..common::HarnessOptions::default()
},
);
let work = harness.dir.path().join("work");
local_repo(&harness, &work, HashKind::Sha1, "correlated\n");
harness
.git(
&work,
&["push", &harness.url("team", "correlated"), "--mirror"],
)
.expect_ok("seed over ssh");
let mark = captured.mark();
let back = harness.dir.path().join("back");
harness
.git_http(
harness.dir.path(),
&[
"clone",
"--quiet",
&harness.http_url("team", "correlated"),
back.to_str().unwrap(),
],
)
.expect_ok("clone over http");
let lines = captured.since(mark);
assert!(
!lines.is_empty(),
"the HTTP clone emitted nothing at all; every assertion below would be vacuous"
);
// Filtered to THIS test's repository, and that is load-bearing. The capture
// is one global buffer for the whole test binary and cargo runs the file in
// parallel, so `since(mark)` is a time slice over every test at once: a
// concurrent SSH clone in another test emits its own
// `git.upload_pack.served`, lands in this window, has `conn` instead of
// `req` and no `http.request` span, and fails the loop below naming a
// transfer this test never made.
//
// MEASURED 2026-08-05: that is exactly how this failed under `cargo xtask
// ci` on a box running four other suites at once, while passing 5/5 runs on
// an idle one — a flake whose message accused `spawn_transport` of a bug
// that was not there. `repo` is on the connection span of both transports,
// and `team/correlated` is this test's alone.
let served: Vec<&Line> = lines
.iter()
.filter(|line| line.get("event") == Some("git.upload_pack.served"))
.filter(|line| line.inherited.get("repo").map(String::as_str) == Some("team/correlated"))
.collect();
assert!(
!served.is_empty(),
"no upload-pack was served over HTTP for team/correlated, so there is no transfer to \
correlate:\n{}",
render(&lines)
);
for line in &served {
let req = line.inherited.get("req").unwrap_or_else(|| {
panic!(
"the served line carries no req. `spawn_transport`'s task is outside \
`http.request`, so the id the client was handed names nothing in this log. \
fields={:?} inherited={:?} spans={:?}",
line.fields, line.inherited, line.spans
)
});
assert_eq!(
req.len(),
16,
"a RequestId renders as 16 hex digits: {req:?}"
);
assert!(
line.spans.iter().any(|name| name == "http.request"),
"the served line is not under `http.request`: spans={:?}",
line.spans
);
// Inherited, NOT restated. `transport.rs` names neither of these on
// this line — the same property the SSH test asserts — so a future
// call site that went back to repeating them by hand would not
// satisfy this.
assert_eq!(
line.inherited.get("repo").map(String::as_str),
Some("team/correlated"),
"the span does not carry the repository: inherited={:?}",
line.inherited
);
assert!(
line.inherited.contains_key("principal"),
"the span does not carry the principal: inherited={:?}",
line.inherited
);
}
// Every line of this clone shares ONE id, which is what makes it greppable.
let ids: BTreeSet<&str> = lines
.iter()
.filter_map(|line| line.inherited.get("req").map(String::as_str))
.collect();
assert!(
!ids.is_empty(),
"not one line of the HTTP clone carried a req"
);
}
/// **An LFS object transfer over HTTP is under the same one id.**
///
/// The twin of the test above, for the surface added on 2026-08-05, and it
/// exists because that surface broke exactly the property that one asserts —
/// and broke it in a place `spawn_transport`'s `.instrument(…)` does not reach.
///
/// A streamed download runs in `tokio::task::spawn_blocking`, which is a
/// **thread hand-off, not a task spawn**: `.instrument(…)` is for futures and
/// does not apply, and the current span is thread-local, so the closure starts
/// with no span at all. MEASURED against a live `gunnar serve` on 2026-08-05:
/// every `http.lfs.*` line sat inside `http.request` except
/// `http.lfs.download.served` — the one line that says how many object bytes
/// actually moved — which came out bare.
///
/// It asserts on **`http.lfs.download.served`** and not on the batch line
/// precisely for that reason: the batch is awaited in the request's own task
/// and would be correlated whether or not anyone thought about it.
///
/// Seen red: with `let _entered = span.enter();` removed from the download's
/// blocking closure, this fails with *"the served-object line carries no req"*,
/// and only this test fails.
#[cfg(feature = "http")]
#[test]
fn an_lfs_object_served_over_http_is_under_the_request_span() {
use std::sync::Arc;
let captured = capture::install();
let harness = common::Harness::start_with_options(
"team",
"lfscorrelated",
HashKind::Sha256,
common::HarnessOptions {
http: true,
..common::HarnessOptions::default()
},
);
let token = harness.mint_token("tester");
let addr = harness.http_addr.expect("the http listener");
// Put an object in through the store the server itself uses, so the test
// is about the READ path and not about whether an upload works.
let content = b"a small object with a large log".to_vec();
let oid = gunnar_lfs::Oid::of(&content);
let lfs = gunnar_lfs::FsLfsStore::open_or_init(harness.git_dir("team", "lfscorrelated"))
.expect("open the lfs store");
{
use gunnar_lfs::LfsStore as _;
let mut pending = lfs.begin_write(&oid, content.len() as u64).expect("begin");
std::io::Write::write_all(&mut pending, &content).expect("write");
pending.commit().expect("commit");
}
let _ = Arc::new(());
let mark = captured.mark();
let body = lfs_http_get(
addr,
&format!("/team/lfscorrelated.git/info/lfs/objects/{oid}"),
&token,
);
assert_eq!(
body, content,
"the object did not come back, so there is no transfer to correlate"
);
// The served line is written after the last byte, so the client can have the whole
// body before it exists: wait for it (bounded), never read the capture at once.
let lines = captured.since_when(mark, std::time::Duration::from_secs(30), |lines| {
lines
.iter()
.any(|line| line.get("event") == Some("http.lfs.download.served"))
});
assert!(
!lines.is_empty(),
"the LFS download emitted nothing at all; every assertion below would be vacuous"
);
let served: Vec<&Line> = lines
.iter()
.filter(|line| line.get("event") == Some("http.lfs.download.served"))
.collect();
assert!(
!served.is_empty(),
"no lfs object was reported served:\n{}",
render(&lines)
);
for line in &served {
let req = line.inherited.get("req").unwrap_or_else(|| {
panic!(
"the served-object line carries no req. The download runs in \
`spawn_blocking`, which does not carry the current span across, so the id \
the client was handed names nothing in this log. \
fields={:?} inherited={:?} spans={:?}",
line.fields, line.inherited, line.spans
)
});
assert_eq!(
req.len(),
16,
"a RequestId renders as 16 hex digits: {req:?}"
);
assert!(
line.spans.iter().any(|name| name == "http.request"),
"the served-object line is not under `http.request`: spans={:?}",
line.spans
);
// Inherited, not restated: `lfs.rs` names neither on this line.
assert_eq!(
line.inherited.get("repo").map(String::as_str),
Some("team/lfscorrelated"),
"inherited={:?}",
line.inherited
);
assert_eq!(
line.inherited.get("principal").map(String::as_str),
Some("tester"),
"inherited={:?}",
line.inherited
);
// And the applied output is on it: bytes that really moved.
assert_eq!(
line.get("bytes").map(str::to_owned),
Some(content.len().to_string()),
"the line must report the bytes that moved, not merely that a download \
happened: fields={:?}",
line.fields
);
}
}
/// One authenticated `GET` against the LFS object endpoint, returning the body.
///
/// Hand-written for the same reason `tests/http_transport.rs` writes its own
/// requests: nothing in this tree links an HTTP client, and `Connection: close`
/// plus read-to-EOF is all this needs.
#[cfg(feature = "http")]
fn lfs_http_get(addr: std::net::SocketAddr, path: &str, token: &str) -> Vec<u8> {
use base64ct::Encoding as _;
use std::io::{Read as _, Write as _};
let credential = base64ct::Base64::encode_string(format!("x-access-token:{token}").as_bytes());
let mut stream = std::net::TcpStream::connect(addr).expect("connect");
stream
.write_all(
format!(
"GET {path} HTTP/1.1\r\nHost: {addr}\r\nConnection: close\r\n\
Authorization: Basic {credential}\r\nContent-Length: 0\r\n\r\n"
)
.as_bytes(),
)
.expect("write the request");
stream.flush().expect("flush");
let mut raw = Vec::new();
stream.read_to_end(&mut raw).expect("read the response");
let split = raw
.windows(4)
.position(|window| window == b"\r\n\r\n")
.expect("a header terminator");
let status = String::from_utf8_lossy(&raw[..raw.iter().position(|b| *b == b'\r').unwrap_or(0)])
.into_owned();
assert!(
status.contains(" 200 "),
"the object endpoint answered {status:?}: {}",
String::from_utf8_lossy(&raw[split + 4..])
);
raw[split + 4..].to_vec()
}
// ───────────────────────────────────────────────────────────────────────────
// The gRPC request span
// ───────────────────────────────────────────────────────────────────────────
/// **A refused control-plane call hands the caller the id of the line that
/// refused it.**
///
/// This is the whole point of the request id, and it is asserted as a
/// **join**, not as
/// two facts. `Admin.Health` is called twice over a real `tonic` channel
/// against a real `gunnar serve`: once with no credential at all, once with the
/// harness's sshsig. For each call the test reads `gunnar-request-id` out of
/// what the *client* got back — the `tonic::Status` metadata on the refusal,
/// the response metadata on the success — and then requires the server's own
/// captured `grpc.request.done` line to carry **that same value** in `req`.
///
/// A test that only checked "the server logged a req" would pass against a
/// server that minted a fresh id for the log and sent the client a different
/// one, which is a correlation that reads as working and is not one.
///
/// It also pins the three things the layer exists to add and an interceptor
/// could not:
///
/// * `elapsed_ms`, which needs the response;
/// * `grpc_status`, which needs the response;
/// * `gunnar::audit`'s authorisation record **inheriting** `req` from the span,
/// which needs the span to still be open while the handler runs.
///
/// # Seen red
///
/// With `.layer(RequestSpanLayer::new(request_ids))` removed from
/// `gunnar_grpc::router`, this fails at the first assertion — *"the refusal
/// carried no gunnar-request-id"* — and nothing else in the suite fails, so it
/// is pinned to the layer and not to the control plane. With the
/// `response.headers_mut().insert(...)` line moved inside the success arm, the
/// refusal half fails and the success half still passes, which is the
/// asymmetry that made `report_error` reachable from nowhere.
#[test]
fn a_grpc_call_carries_one_id_the_caller_gets_and_the_server_logs() {
let captured = capture::install();
let mark = captured.mark();
let harness = Harness::start_with_grpc("team", "grpc-span", HashKind::Sha1);
// ── the refusal: no credential at all ──────────────────────────────────
let url = harness.grpc_url();
let refused = harness.runtime.block_on(async {
let channel = tonic::transport::Channel::from_shared(url.clone())
.expect("a valid endpoint")
.connect()
.await
.expect("connect to the control plane");
let mut client = gunnar_proto::admin_client::AdminClient::new(channel);
client
.health(tonic::Request::new(gunnar_proto::HealthRequest {}))
.await
.expect_err("an uncredentialed Admin.Health must be refused")
});
assert_eq!(
refused.code(),
tonic::Code::Unauthenticated,
"the refusal is not the one this test is about: {refused:?}"
);
let refused_id = refused
.metadata()
.get(gunnar_grpc::REQUEST_ID_METADATA_KEY)
.and_then(|value| value.to_str().ok())
.unwrap_or_else(|| {
panic!(
"the refusal carried no {}, so the caller has nothing to grep the server log \
for: metadata={:?}",
gunnar_grpc::REQUEST_ID_METADATA_KEY,
refused.metadata()
)
})
.to_owned();
// ── the success: the harness's real sshsig credential ──────────────────
let (served_id, health) = harness.runtime.block_on(async {
let channel = tonic::transport::Channel::from_shared(url)
.expect("a valid endpoint")
.connect()
.await
.expect("connect to the control plane");
let mut client = gunnar_proto::admin_client::AdminClient::new(channel);
let response = client
.health(harness.authed("Admin.Health", gunnar_proto::HealthRequest {}))
.await
.expect("a credentialed Admin.Health");
let id = response
.metadata()
.get(gunnar_grpc::REQUEST_ID_METADATA_KEY)
.and_then(|value| value.to_str().ok())
.map(str::to_owned);
(id, response.into_inner())
});
assert!(
!health.agent.is_empty(),
"Admin.Health answered nothing, so the success half asserts nothing"
);
let served_id = served_id.expect("a served response carries the request id too");
assert_ne!(
served_id, refused_id,
"two calls got the SAME id, so the counter is not moving and every line in the log is \
filed under one identifier"
);
let lines = captured.since(mark);
// ── the join, once per call ─────────────────────────────────────────────
for (id, want_refusal) in [(&refused_id, true), (&served_id, false)] {
let done = lines
.iter()
.filter(|line| line.get("event") == Some("grpc.request.done"))
.find(|line| line.get("req") == Some(id.as_str()))
.unwrap_or_else(|| {
panic!(
"the caller was given req={id} and NO server line carries it, so the id the \
client holds names nothing:\n{}",
render(&lines)
)
});
assert_eq!(
done.spans.last().map(String::as_str),
Some("grpc.request"),
"the exit line is not under `grpc.request`: spans={:?}",
done.spans
);
// Inherited from the span, not restated: the exit line names no `req`
// of its own, so this is the span carrying it across the handler.
assert_eq!(
done.inherited("req"),
Some(id.as_str()),
"req is stated on the event rather than inherited from the span, which means the \
span does not span the call: inherited={:?}",
done.inherited
);
assert!(
done.inherited("method")
.is_some_and(|m| m.contains("Health")),
"the span does not name the method: inherited={:?}",
done.inherited
);
// The two fields only a layer can produce.
assert!(
done.get("elapsed_ms").is_some(),
"no elapsed_ms, so 'is it slow' is still unanswerable: {done:?}"
);
assert_eq!(
done.get("http_status"),
Some("200"),
"gRPC answers 200 and puts its own status in grpc-status; a different code here \
means the transport failed rather than the call: {done:?}"
);
if want_refusal {
assert_eq!(done.level, "warn", "a refusal must survive RUST_LOG=warn");
assert_eq!(
done.get("grpc_status"),
// 16 = UNAUTHENTICATED.
Some("16"),
"the refusal's grpc-status is not on the line, so the log cannot say WHY the \
caller's call failed: {done:?}"
);
} else {
assert_eq!(done.level, "info");
// An ABSENCE, rendered as absent. tonic puts `grpc-status: 0` in the
// TRAILERS of a success, which this layer cannot read, and logging a
// `0` it never saw is how `pack_bytes` came to render a failed
// `stat` as a measurement.
assert_eq!(
done.get("grpc_status"),
None,
"a success logged a grpc_status the layer never read: {done:?}"
);
}
}
// ── the audit record inherits the id ───────────────────────────────────
//
// This is the join an operator actually walks: from the caller's error, to
// the exit line, to the record that names the principal and the decision.
// The audit record is written by `gunnar-grpc`'s gate, three functions
// inside the layer, and names no `req` itself.
let audit = lines
.iter()
.filter(|line| line.target == "gunnar::audit")
.filter(|line| line.get("method").is_some_and(|m| m.contains("Health")))
.filter(|line| line.get("event") != Some("grpc.request.done"))
.filter(|line| line.get("event") != Some("grpc.request.begin"))
.find(|line| line.inherited("req") == Some(served_id.as_str()))
.unwrap_or_else(|| {
panic!(
"no authorisation record for the served call inherited req={served_id}; the \
span closed before the handler ran, which is exactly what a tonic INTERCEPTOR \
would have produced:\n{}",
render(&lines)
)
});
assert!(
audit.get("principal").is_some(),
"the audit record names no principal, so the join leads nowhere: {audit:?}"
);
drop(harness);
}
/// **`gunnar-grpc` renders a request id exactly as `gunnar-core` does.**
///
/// `gunnar-grpc` deliberately has no `gunnar-core` edge (it would put
/// `gunnar-store`, `aws-lc-rs` and a C build script into the
/// `--features client,control` graph), so the *rendering* of the id is stated in
/// both crates. `gunnar-cli` links both, which makes this the one place the two
/// spellings can be compared — the same reason
/// `the_audit_target_is_the_same_string_in_both_crates` exists.
///
/// A shared counter rendered two ways is still two identifiers: a log line
/// reading `req=1a2b` and a client holding `0x1a2b` do not join.
///
/// Seen red: with `render_request_id`'s `{id:016x}` changed to `{id:x}`, this
/// fails on the low-value id, which is exactly the case a hand-check would
/// miss.
#[test]
fn the_grpc_request_id_renders_exactly_as_gunnar_core_renders_one() {
use gunnar_core::observe::RequestId;
let id = RequestId::next();
assert_eq!(
gunnar_grpc::render_request_id(id.get()),
id.to_string(),
"the two crates spell the same id differently"
);
// And at the edges, where a width bug hides: `RequestId::next` never
// returns a small number (the high half is a process seed), so a test that
// only used a real id could not see a missing zero pad.
for raw in [0u64, 1, 0xff, 0xdead_beef, u64::MAX] {
assert_eq!(
gunnar_grpc::render_request_id(raw),
format!("{raw:016x}"),
"raw={raw:#x}"
);
}
}
// ───────────────────────────────────────────────────────────────────────────
// The journal an operator greps
// ───────────────────────────────────────────────────────────────────────────
/// **A healthy transfer must leave nothing behind that `grep -i error` finds.**
///
/// # The defect
///
/// MEASURED 2026-08-06, from the live server's own journal at
/// `10:55:10`, for one `ls-remote` that fully succeeded:
///
/// ```text
/// INFO served git-upload-pack event="git.upload_pack.served" … bytes_out=265
/// DEBUG ssh session ended with an error error=early eof
/// WARN the client was gone before the exit status channel=ChannelId(2) status=0
/// DEBUG a session teardown step did not complete event="ssh.teardown.failed" \
/// step="channel-close" err=Channel send error
/// INFO transfer finished event="git.transfer.finished" status=0 elapsed_ms=106
/// ```
///
/// Nothing was damaged. `status=0`, `transfer finished`. But three of the five
/// lines carry `error`, `err` or `failed`, and the audit counted 12 + 6 of them
/// across 9 successful transfers. `grep -i error` in gunnar's journal is the
/// first thing an operator runs when something is wrong, and on this server it
/// returned a wall of healthy traffic. That is not a cosmetic problem: it is
/// the reason a real error would be missed.
///
/// # What is asserted, and why it is the operator's own grep
///
/// Not "the three known lines are gone" — that would pass the day a fourth
/// appears. The rule is stated the way the operator states it: **no line
/// produced by a healthy transfer may match `error`, `err=` or `fail`,
/// case-insensitively, in its level, its message, or any field name or value.**
///
/// # Anti-vacuity
///
/// A capture with nothing in it satisfies "no error lines" perfectly, so the
/// transfer is proved to have happened first, on its applied output: a
/// `git.transfer.finished` with `status=0`, and an `ls-refs` that really
/// advertised the branch.
///
/// # What this test can NOT see, stated rather than glossed
///
/// Two of the three noisy lines are emitted under the connection span and are
/// caught here — MEASURED against the pre-fix server, which fails this test
/// naming exactly `git.exit_status.undelivered` at `warn` and
/// `ssh.teardown.failed err=Channel send error`.
///
/// The third, `ssh session ended with an error error=early eof`, comes from
/// `russh::server::Server::handle_session_error`, which has **no connection
/// context at all** — russh calls it on the server, not on the session, so the
/// line carries no `conn` and [`for_repo`] cannot attribute it. Filtering the
/// whole capture instead would read other tests' lines, since this file's tests
/// share one process and one subscriber. That line is therefore guarded where
/// it is decided instead: `gunnar-ssh`'s
/// `server::tests::a_hung_up_session_is_not_logged_as_an_error`, which drives
/// the same `note_session_end` russh calls, in both directions.
///
/// (That the line is unattributable at all is a real, separate observability
/// gap — every other line in a connection carries `conn` — and it is recorded
/// in `PLAN.md` rather than fixed here; it needs a russh API that does not
/// exist in 0.61.)
#[test]
fn a_healthy_transfer_logs_nothing_an_operator_would_grep_as_an_error() {
assert!(
tools_present(),
"this test requires `git` and `ssh` on PATH"
);
let captured = capture::install();
let harness = Harness::start("team", "quiet", HashKind::Sha1);
let work = harness.dir.path().join("quiet-work");
local_repo(&harness, &work, HashKind::Sha1, "a quiet transfer\n");
let url = harness.url("team", "quiet");
harness
.git(&work, &["push", &url, "--all"])
.expect_ok("seed the repository");
let mark = captured.mark();
// gunnar's OWN client, because it is the one that produces the race: it
// reads the advertisement and lets the channel go, where stock `ssh` waits
// for `exit-status` before exiting. Driving stock git here would make this
// test green against the broken server.
let out = Command::new(env!("CARGO_BIN_EXE_gunnar-cli"))
.args(["ls-remote", "-i"])
.arg(&harness.key_path)
.arg(&url)
.env("HOME", harness.dir.path())
.env("SSH_AUTH_SOCK", "")
.output()
.expect("run the gunnar binary");
assert!(
out.status.success(),
"the transfer under test did not succeed, so its journal is not a HEALTHY \
transfer's journal.\nstdout: {}\nstderr: {}",
String::from_utf8_lossy(&out.stdout),
String::from_utf8_lossy(&out.stderr),
);
// Give the server's spawned transfer task time to run its teardown; the
// client has already exited by then, which is the whole point.
std::thread::sleep(std::time::Duration::from_millis(500));
let lines = for_repo(&captured.since(mark), "team/quiet");
// ── anti-vacuity: the transfer really happened, and really served refs ──
let finished = one(&lines, "git.transfer.finished");
assert_eq!(
finished.get("status"),
Some("0"),
"this is not a healthy transfer, so its noise is not the noise under test"
);
assert!(
String::from_utf8_lossy(&out.stdout).contains("refs/heads/"),
"no refs were advertised, so nothing was transferred to be quiet about"
);
// ── the operator's grep ────────────────────────────────────────────────
let smells = |s: &str| {
let s = s.to_ascii_lowercase();
s.contains("error") || s.contains("err=") || s.contains("fail")
};
let offenders: Vec<&Line> = lines
.iter()
.filter(|line| {
smells(&line.level)
|| smells(&line.message)
|| line.fields.iter().any(|(k, v)| smells(k) || smells(v))
})
.collect();
assert!(
offenders.is_empty(),
"a HEALTHY transfer left {} line(s) that `grep -i error` finds, which is what \
makes that grep useless on a working server:\n{}\n\n--- the whole transfer ---\n{}",
offenders.len(),
offenders
.iter()
.map(|l| format!(
" [{}] {} {:?} fields={:?}",
l.level, l.target, l.message, l.fields
))
.collect::<Vec<_>>()
.join("\n"),
render(&lines)
);
drop(harness);
}