Add the audit writer with its startup check

Implemented-By: OpenCode session (model recorded in docs/implementer-log.md)
This commit is contained in:
2026-09-19 16:32:37 -07:00
parent a301915551
commit ded7eb8c50
6 changed files with 1081 additions and 0 deletions
+258
View File
@@ -0,0 +1,258 @@
//! The audit writer: the chain it writes, the lock, rollover, and stopping after a failed
//! write. Do not edit. Startup checks, recovery and accepted breaks are in `audit_startup.rs`.
#[path = "support/audit_dir.rs"]
mod audit_dir;
use std::os::unix::fs::PermissionsExt;
use audit_dir::{D1, D2, TempDir, denied, lines, ts};
use brokerd::audit::{AuditError, RECOVERED_NOTICE, Writer, verify_dir};
use proto::{AuditRecord, Hash32, sha256};
fn mode(path: &std::path::Path) -> u32 {
std::fs::metadata(path).unwrap().permissions().mode() & 0o777
}
#[test]
fn the_first_record_starts_the_chain() {
let dir = TempDir::unmade("first");
let opened = Writer::open(&dir.path, false).unwrap();
assert!(!opened.recovered);
assert!(opened.accepted.is_none());
let mut writer = opened.writer;
assert_eq!(writer.next_seq(), 0);
let seq = writer
.append(ts("2026-09-17T08:00:00.000Z"), denied(1))
.unwrap();
assert_eq!(seq, 0);
assert_eq!(writer.next_seq(), 1);
let text = std::fs::read_to_string(dir.path.join(D1)).unwrap();
assert!(text.ends_with('\n'), "a record is one line and its newline");
assert_eq!(text.lines().count(), 1);
let record: AuditRecord = serde_json::from_str(text.lines().next().unwrap()).unwrap();
assert_eq!((record.seq, record.prev), (0, Hash32::ZERO));
assert_eq!(record.time, ts("2026-09-17T08:00:00.000Z"));
assert_eq!(record.event, denied(1));
assert_eq!(mode(&dir.path), 0o700, "the directory open() made");
assert_eq!(mode(&dir.path.join(D1)), 0o600);
}
#[test]
fn the_chain_runs_across_a_day_boundary() {
let dir = TempDir::unmade("days");
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
let times = [
"2026-09-17T23:59:58.000Z",
"2026-09-17T23:59:59.999Z",
"2026-09-18T00:00:00.000Z",
"2026-09-18T00:00:01.000Z",
];
for (i, time) in times.iter().enumerate() {
assert_eq!(writer.append(ts(time), denied(i as u64)).unwrap(), i as u64);
}
let (day1, day2) = (lines(&dir.path, D1), lines(&dir.path, D2));
assert_eq!((day1.len(), day2.len()), (2, 2));
// seq goes on across files, and the new file chains from the last line of the old one.
let first: AuditRecord = serde_json::from_str(&day2[0]).unwrap();
assert_eq!(first.seq, 2);
assert_eq!(first.prev, sha256(day1[1].as_bytes()).unwrap());
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None);
assert_eq!((report.records, report.next_seq), (4, 4));
assert!(report.clock_warnings.is_empty());
}
#[test]
fn reopening_continues_the_chain() {
let dir = TempDir::unmade("reopen");
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
writer
.append(ts("2026-09-17T08:00:00.000Z"), denied(1))
.unwrap();
writer
.append(ts("2026-09-17T08:00:01.000Z"), denied(2))
.unwrap();
drop(writer);
// One file: the whole of it is checked.
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
assert_eq!(writer.next_seq(), 2);
assert_eq!(
writer
.append(ts("2026-09-18T08:00:00.000Z"), denied(3))
.unwrap(),
2
);
drop(writer);
// Two files: the latest is checked, resumed from the last line of the one before.
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
assert_eq!(writer.next_seq(), 3);
assert_eq!(
writer
.append(ts("2026-09-18T08:00:01.000Z"), denied(4))
.unwrap(),
3
);
drop(writer);
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None);
assert_eq!(report.records, 4);
}
#[test]
fn an_empty_latest_file_gets_the_next_record_as_its_first_line() {
let dir = TempDir::case("empty-latest", None);
let opened = Writer::open(&dir.path, false).unwrap();
assert!(!opened.recovered);
let mut writer = opened.writer;
assert_eq!(
writer
.append(ts("2026-09-18T08:00:00.000Z"), denied(9))
.unwrap(),
5
);
let day2 = lines(&dir.path, D2);
assert_eq!(day2.len(), 1);
let record: AuditRecord = serde_json::from_str(&day2[0]).unwrap();
assert_eq!(
record.prev,
sha256(lines(&dir.path, D1)[4].as_bytes()).unwrap()
);
assert_eq!(verify_dir(&dir.path).unwrap().failure, None);
}
#[test]
fn a_second_writer_is_refused() {
let dir = TempDir::unmade("lock");
let first = Writer::open(&dir.path, false).unwrap();
let error = Writer::open(&dir.path, false).unwrap_err();
assert!(matches!(error, AuditError::Locked), "{error}");
let text = error.to_string();
assert!(text.starts_with("brokerd is already running"), "{text}");
assert!(
text.ends_with("see docs/runbook.md#brokerd-already-running"),
"{text}"
);
// The lock goes when the writer goes, however that happens.
drop(first);
assert!(Writer::open(&dir.path, false).is_ok());
}
#[test]
fn the_writer_never_goes_back_to_an_earlier_file() {
let dir = TempDir::unmade("clock");
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
writer
.append(ts("2026-09-18T00:00:05.000Z"), denied(1))
.unwrap();
// The clock is stepped back over midnight.
writer
.append(ts("2026-09-17T23:59:50.000Z"), denied(2))
.unwrap();
assert!(
!dir.path.join(D1).exists(),
"a record went into an earlier file"
);
assert_eq!(lines(&dir.path, D2).len(), 2);
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None);
assert_eq!(report.clock_warnings.len(), 1);
// It holds across a restart too.
drop(writer);
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
writer
.append(ts("2026-09-17T23:59:55.000Z"), denied(3))
.unwrap();
assert!(!dir.path.join(D1).exists());
assert_eq!(verify_dir(&dir.path).unwrap().failure, None);
}
#[test]
fn files_that_are_not_log_files_are_ignored() {
let dir = TempDir::case("good", None);
std::fs::write(dir.path.join("notes.txt"), "not a log\n").unwrap();
std::fs::write(dir.path.join("2026-09-19.jsonl.bak"), "not a log\n").unwrap();
std::fs::write(dir.path.join("latest.jsonl"), "not a log\n").unwrap();
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
assert_eq!(writer.next_seq(), 10);
writer
.append(ts("2026-09-18T10:00:00.000Z"), denied(9))
.unwrap();
assert_eq!(verify_dir(&dir.path).unwrap().records, 11);
}
/// After one failed write the writer writes nothing more, even when the cause has gone: part of
/// a line may be on disk, and only the next start deals with that.
#[test]
fn a_failed_write_stops_the_writer() {
let dir = TempDir::unmade("sticky");
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
writer
.append(ts("2026-09-17T08:00:00.000Z"), denied(1))
.unwrap();
// A new day needs a new file, and the directory no longer allows one.
std::fs::set_permissions(&dir.path, std::fs::Permissions::from_mode(0o500)).unwrap();
if std::fs::write(dir.path.join("probe"), "").is_ok() {
eprintln!("skipped: this user can write to a read-only directory (root?)");
std::fs::set_permissions(&dir.path, std::fs::Permissions::from_mode(0o700)).unwrap();
return;
}
let error = writer
.append(ts("2026-09-18T08:00:00.000Z"), denied(2))
.unwrap_err();
assert!(matches!(error, AuditError::Io { .. }), "{error}");
assert!(
error
.to_string()
.ends_with("see docs/runbook.md#audit-unavailable"),
"{error}"
);
std::fs::set_permissions(&dir.path, std::fs::Permissions::from_mode(0o700)).unwrap();
for time in ["2026-09-18T08:00:01.000Z", "2026-09-17T08:00:02.000Z"] {
let error = writer.append(ts(time), denied(3)).unwrap_err();
assert!(matches!(error, AuditError::Stopped), "{error}");
assert!(
error
.to_string()
.ends_with("see docs/runbook.md#audit-unavailable"),
"{error}"
);
}
assert_eq!(
lines(&dir.path, D1).len(),
1,
"a stopped writer wrote something"
);
assert!(!dir.path.join(D2).exists());
// A restart puts it right.
drop(writer);
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
assert_eq!(
writer
.append(ts("2026-09-18T08:00:03.000Z"), denied(4))
.unwrap(),
1
);
assert_eq!(verify_dir(&dir.path).unwrap().failure, None);
}
#[test]
fn the_recovered_notice_names_its_runbook_entry() {
assert!(RECOVERED_NOTICE.starts_with("audit: recovered a torn final line"));
assert!(RECOVERED_NOTICE.ends_with("see docs/runbook.md#audit-recovered"));
}
+300
View File
@@ -0,0 +1,300 @@
//! What `Writer::open` does with the log it finds: refuse a broken chain, recover a torn tail,
//! accept a break when told to. Do not edit. The fixture logs are in
//! `crates/proto/tests/fixtures/audit/`; each test works on a copy.
#[path = "support/audit_dir.rs"]
mod audit_dir;
use audit_dir::{D1, D2, TempDir, denied, lines, snapshot};
use brokerd::audit::{AuditError, Writer, verify_dir};
use proto::{AuditEvent, AuditRecord, Location, Timestamp};
type Case = (
&'static str,
Option<&'static [&'static str]>,
&'static str,
u64,
&'static str,
);
fn at(file: &str, line: u64) -> Location {
Location {
file: file.to_string(),
line,
}
}
/// An ordinary start checks the latest file only, so each damaged file is copied alone: it is
/// then the latest. Nothing may be written to a log that does not verify.
#[test]
fn a_broken_chain_refuses_to_start_and_writes_nothing() {
let parse = "does not parse as an audit record";
// (case, the files to copy, then the failure's file, line and text)
let cases: [Case; 9] = [
(
"changed-byte",
Some(&[D1]),
D1,
4,
"prev is not the hash of the line before",
),
("deleted-line", Some(&[D1]), D1, 3, "seq is 3, expected 2"),
("swapped-lines", Some(&[D1]), D1, 2, "seq is 2, expected 1"),
("seq-gap", None, D1, 3, "seq is 3, expected 2"),
("cut-short", Some(&[D1]), D1, 3, parse),
// Both files: the latest does not chain from the last line of the one before.
(
"file-not-chained",
None,
D2,
1,
"does not chain from the last line of the file before",
),
(
"break-without-failure",
None,
D2,
6,
"an accepted break with no failure before it",
),
("recovery-wrong-hash", None, D2, 6, parse),
("torn-recovery", None, D2, 6, parse),
];
for (case, only, file, line, what) in cases {
let dir = TempDir::case(case, only);
let before = snapshot(&dir.path);
let error = Writer::open(&dir.path, false)
.err()
.unwrap_or_else(|| panic!("{case}: started"));
let AuditError::Broken(failure) = &error else {
panic!("{case}: {error}");
};
assert_eq!(
(failure.file.as_str(), failure.line, failure.what.as_str()),
(file, line, what),
"{case}"
);
let text = error.to_string();
assert!(
text.starts_with(&format!("{file}:{line}: {what}")),
"{case}: {text}"
);
assert!(
text.ends_with("see docs/runbook.md#audit-chain-broken"),
"{case}: {text}"
);
assert_eq!(
snapshot(&dir.path),
before,
"{case}: the log was written to"
);
}
}
/// A torn tail is recovered: the torn bytes stay, a newline ends them if one is missing, and a
/// `Recovery` record follows in the same file, whatever today's date is.
#[test]
fn a_torn_tail_is_recovered() {
// (case, the torn line's file and number, newline already there)
let cases = [
("torn-tail", D2, 6, false),
("torn-tail-complete-json", D2, 6, false),
("torn-unparseable-newline", D2, 6, true),
("torn-first-line", D2, 1, false),
];
for (case, file, line, has_newline) in cases {
let dir = TempDir::case(case, None);
let before = snapshot(&dir.path);
let opened = Writer::open(&dir.path, false).unwrap_or_else(|e| panic!("{case}: {e}"));
assert!(opened.recovered, "{case}");
assert!(opened.accepted.is_none(), "{case}");
let after = snapshot(&dir.path);
assert_eq!(
after.len(),
before.len(),
"{case}: the Recovery went into a new file"
);
let (old, new) = (&before[file], &after[file]);
assert!(
new.starts_with(old),
"{case}: bytes already on disk were changed"
);
let added = &new[old.len()..];
// One newline to end the torn line if it had none, then one line.
let added = if has_newline {
added
} else {
added.strip_prefix(b"\n").expect(case)
};
assert_eq!(added.iter().filter(|b| **b == b'\n').count(), 1, "{case}");
let record: AuditRecord =
serde_json::from_slice(added.strip_suffix(b"\n").expect(case)).expect(case);
assert!(
matches!(record.event, AuditEvent::Recovery { .. }),
"{case}"
);
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None, "{case}");
assert_eq!(report.torn_tail, None, "{case}");
assert_eq!(report.recoveries, vec![at(file, line)], "{case}");
// The chain goes on from the Recovery, and the next start finds nothing to recover.
let mut writer = opened.writer;
assert_eq!(
writer.append(Timestamp::now(), denied(9)).unwrap(),
record.seq + 1,
"{case}"
);
drop(writer);
let opened = Writer::open(&dir.path, false).unwrap();
assert!(!opened.recovered, "{case}");
assert_eq!(verify_dir(&dir.path).unwrap().failure, None, "{case}");
}
}
/// Damage in an older file is not seen by an ordinary start. `bxctl audit verify` sees it, and
/// `--accept-break` must too: it verifies the whole log.
#[test]
fn a_break_in_an_older_file_can_be_accepted() {
let dir = TempDir::case("changed-byte", None);
let before = snapshot(&dir.path);
drop(Writer::open(&dir.path, false).expect("the latest file verifies"));
assert_eq!(snapshot(&dir.path), before);
let failure = verify_dir(&dir.path).unwrap().failure.unwrap();
assert_eq!((failure.file.as_str(), failure.line), (D1, 4));
let opened = Writer::open(&dir.path, true).unwrap();
assert!(!opened.recovered);
assert_eq!(
opened.accepted.as_ref().map(|f| (f.file.as_str(), f.line)),
Some((D1, 4))
);
let after = snapshot(&dir.path);
assert_eq!(after[D1], before[D1], "nothing is repaired");
assert!(after[D2].starts_with(&before[D2]));
let last: AuditRecord = serde_json::from_str(lines(&dir.path, D2).last().unwrap()).unwrap();
assert_eq!(
last.event,
AuditEvent::AcceptedBreak {
file: D1.to_string(),
line: 4,
last_good: failure.last_good,
}
);
assert_eq!(
last.seq, 10,
"seq 3 for the failing line, and seven lines to the break"
);
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None);
assert_eq!(report.accepted_breaks, vec![at(D2, 6)]);
let mut writer = opened.writer;
assert_eq!(writer.append(Timestamp::now(), denied(9)).unwrap(), 11);
drop(writer);
// The next ordinary start resumes at the latest file and meets a break that names a file
// it has not read.
let mut writer = Writer::open(&dir.path, false).unwrap().writer;
assert_eq!(writer.append(Timestamp::now(), denied(10)).unwrap(), 12);
assert_eq!(verify_dir(&dir.path).unwrap().failure, None);
}
#[test]
fn a_break_in_the_latest_file_can_be_accepted() {
// (case, failing line, seq of the break record)
for (case, line, seq) in [("recovery-wrong-hash", 6, 12), ("torn-recovery", 6, 12)] {
let dir = TempDir::case(case, None);
let before = snapshot(&dir.path);
let opened = Writer::open(&dir.path, true).unwrap_or_else(|e| panic!("{case}: {e}"));
assert_eq!(
opened.accepted.as_ref().map(|f| f.line),
Some(line),
"{case}"
);
let after = snapshot(&dir.path);
assert!(after[D2].starts_with(&before[D2]), "{case}");
// torn-recovery ends without a newline: the break record must start on its own line.
let all = lines(&dir.path, D2);
let last: AuditRecord = serde_json::from_str(all.last().unwrap()).expect(case);
assert!(
matches!(last.event, AuditEvent::AcceptedBreak { .. }),
"{case}"
);
assert_eq!(last.seq, seq, "{case}");
assert_eq!(all.len(), 8, "{case}");
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None, "{case}");
assert_eq!(report.accepted_breaks, vec![at(D2, 8)], "{case}");
drop(opened);
assert!(Writer::open(&dir.path, false).is_ok(), "{case}");
}
}
/// The short check is a shortcut and never the last word: when it cannot be made, or fails, the
/// whole log is verified and that verdict stands. Here the last line of the older file is the
/// damage, so there is nothing to resume from.
#[test]
fn an_accepted_break_at_the_end_of_an_older_file_does_not_stop_later_starts() {
let dir = TempDir::case("good", None);
let day1 = std::fs::read_to_string(dir.path.join(D1)).unwrap();
let cut = format!("{}\n", &day1[..day1.len() - 40]);
std::fs::write(dir.path.join(D1), cut).unwrap();
let error = Writer::open(&dir.path, false).unwrap_err();
let AuditError::Broken(failure) = &error else {
panic!("{error}");
};
assert_eq!((failure.file.as_str(), failure.line), (D1, 5));
drop(Writer::open(&dir.path, true).unwrap());
let mut writer = Writer::open(&dir.path, false)
.expect("the break was accepted")
.writer;
writer.append(Timestamp::now(), denied(9)).unwrap();
assert_eq!(verify_dir(&dir.path).unwrap().failure, None);
}
#[test]
fn accept_break_with_nothing_to_accept_is_an_error() {
for case in ["good", "torn-tail"] {
let dir = TempDir::case(case, None);
let before = snapshot(&dir.path);
let error = Writer::open(&dir.path, true).unwrap_err();
assert!(
matches!(error, AuditError::NothingToAccept),
"{case}: {error}"
);
assert!(error.to_string().starts_with("nothing to accept"), "{case}");
assert_eq!(
snapshot(&dir.path),
before,
"{case}: the log was written to"
);
}
}
/// A second failure after an accepted break needs its own break.
#[test]
fn damage_after_a_break_is_a_new_failure() {
let dir = TempDir::case("accepted-break", None);
drop(Writer::open(&dir.path, false).expect("the fixture verifies"));
let mut text = std::fs::read_to_string(dir.path.join(D1)).unwrap();
text.push_str("{}\n{}\n");
std::fs::write(dir.path.join(D1), text).unwrap();
let error = Writer::open(&dir.path, false).unwrap_err();
let AuditError::Broken(failure) = &error else {
panic!("{error}");
};
assert_eq!((failure.file.as_str(), failure.line), (D1, 8));
drop(Writer::open(&dir.path, true).unwrap());
let report = verify_dir(&dir.path).unwrap();
assert_eq!(report.failure, None);
assert_eq!(report.accepted_breaks, vec![at(D1, 6), at(D1, 10)]);
}
+98
View File
@@ -0,0 +1,98 @@
//! Temporary audit directories for the audit tests. Do not edit.
#![allow(dead_code)] // each test file uses its own part of this
use std::collections::BTreeMap;
use std::path::{Path, PathBuf};
use std::sync::atomic::{AtomicU32, Ordering};
use proto::{AuditEvent, CallId, DataClass, DecisionRecord, SessionId, Timestamp};
pub const D1: &str = "2026-09-17.jsonl";
pub const D2: &str = "2026-09-18.jsonl";
static NEXT: AtomicU32 = AtomicU32::new(0);
/// A directory under the system's temporary directory, removed when dropped.
pub struct TempDir {
pub path: PathBuf,
}
impl TempDir {
/// A path that does not exist yet.
pub fn unmade(tag: &str) -> TempDir {
let n = NEXT.fetch_add(1, Ordering::SeqCst);
let name = format!("brokerd-{tag}-{}-{n}", std::process::id());
let path = std::env::temp_dir().join(name);
let _ = std::fs::remove_dir_all(&path);
TempDir { path }
}
/// A copy of the fixture log `case` from `crates/proto/tests/fixtures/audit/`. With `only`,
/// just those files: damage in an older file is not seen by an ordinary start, so tests of
/// the startup check copy the damaged file alone.
pub fn case(case: &str, only: Option<&[&str]>) -> TempDir {
let dir = TempDir::unmade(case);
std::fs::create_dir_all(&dir.path).unwrap();
let from = format!(
"{}/../proto/tests/fixtures/audit/{case}",
env!("CARGO_MANIFEST_DIR")
);
let mut copied = 0;
for entry in std::fs::read_dir(&from).unwrap_or_else(|e| panic!("{from}: {e}")) {
let entry = entry.unwrap();
let name = entry.file_name().into_string().unwrap();
if only.is_none_or(|names| names.contains(&name.as_str())) {
std::fs::copy(entry.path(), dir.path.join(&name)).unwrap();
copied += 1;
}
}
assert!(copied > 0, "{from}: nothing copied");
dir
}
}
impl Drop for TempDir {
fn drop(&mut self) {
let _ = std::fs::remove_dir_all(&self.path);
}
}
/// Every log file in `dir` with its bytes.
pub fn snapshot(dir: &Path) -> BTreeMap<String, Vec<u8>> {
std::fs::read_dir(dir)
.unwrap()
.map(|entry| entry.unwrap())
.filter(|entry| entry.file_name().to_string_lossy().ends_with(".jsonl"))
.map(|entry| {
let name = entry.file_name().into_string().unwrap();
(name, std::fs::read(entry.path()).unwrap())
})
.collect()
}
pub fn lines(dir: &Path, file: &str) -> Vec<String> {
let text = std::fs::read_to_string(dir.join(file)).unwrap();
text.lines().map(str::to_string).collect()
}
pub fn ts(s: &str) -> Timestamp {
Timestamp::parse(s).unwrap()
}
/// A denied decision for call `call`: an event that leaves nothing open in the report.
pub fn denied(call: u64) -> AuditEvent {
AuditEvent::Decision {
session: SessionId::new("chat-1").unwrap(),
call: CallId(call),
tool: "read_file".to_string(),
arguments: r#"{"path":"/etc/hosts"}"#.to_string(),
outcome: DecisionRecord::Denied {
reason: proto::DenyReason::NoGrant,
},
grant: None,
grant_sha256: None,
taint: DataClass::Private,
untrusted: false,
}
}