test(TASK-050): give each macro-bracketing marker its own file

cmd opens '>>' redirection targets write-exclusive, so when the STARTED
and terminal hook children appended to one shared log concurrently, the
loser of the open race hit a sharing violation and silently dropped its
marker line -- a permanent loss that surfaced as an intermittent
Windows-CI-only failure of the macro-bracketing suite (the engine's exit
drain was verified sound: spawn intent is registered synchronously at
fire time and covers macro-context fires). One file per event makes
writer overlap impossible while keeping every exact-count assertion
byte-identical.
This commit is contained in:
Dark-Alex-17 committed 2026-09-17 01:00:48 -06:00
1 parent 611900057c
commit ad9b319149
1 file changed
+72 -38
+72 -38
View File
@@ -15,6 +15,8 @@ use std::process::{Command, Output, Stdio};
use std::thread; use std::thread;
use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH};
const MARKERS: [&str; 4] = ["STARTED", "COMPLETED", "FAILED", "INTERRUPTED"];
fn fresh_config_dir(label: &str) -> PathBuf { fn fresh_config_dir(label: &str) -> PathBuf {
let unique = SystemTime::now() let unique = SystemTime::now()
.duration_since(UNIX_EPOCH) .duration_since(UNIX_EPOCH)
@@ -35,13 +37,27 @@ impl Drop for TempDirGuard {
} }
} }
/// Builds the hook command that appends `marker` to `log` in the dialect of /// Path of the file `marker`'s hook appends to. Every event gets its OWN
/// the shell the hook engine dispatches through: `sh -c` elsewhere, `cmd /C` /// file because cmd opens `>>` targets write-exclusive (no shared write
/// on Windows. The cmd form parenthesizes the echo because `echo X >> f` /// access): the STARTED and terminal hook children run concurrently, and
/// under cmd writes "X " with a trailing space, which would break exact /// when both appended to one shared log, overlapping opens made the loser
/// marker matching. Both forms double-quote the path, so the command also /// fail with a sharing violation and silently drop its line — a permanent
/// survives YAML single-quoting and spaces in temp paths. /// marker loss that surfaced as a Windows-CI-only flake. Separate files
fn marker_command(marker: &str, log: &Path) -> String { /// make writer overlap impossible: each event fires at most once per
/// bracket, and re-opened brackets are step-separated, so every file has
/// one writer at a time.
fn marker_log(dir: &Path, marker: &str) -> PathBuf {
dir.join(format!("agent-events-{marker}.log"))
}
/// Builds the hook command that appends `marker` to its own marker file, in
/// the dialect of the shell the hook engine dispatches through: `sh -c`
/// elsewhere, `cmd /C` on Windows. The cmd form parenthesizes the echo
/// because `echo X >> f` under cmd writes "X " with a trailing space, which
/// would break exact marker matching. Both forms double-quote the path, so
/// the command also survives YAML single-quoting and spaces in temp paths.
fn marker_command(marker: &str, dir: &Path) -> String {
let log = marker_log(dir, marker);
let log = log.display(); let log = log.display();
if cfg!(windows) { if cfg!(windows) {
format!(r#"(echo {marker})>> "{log}""#) format!(r#"(echo {marker})>> "{log}""#)
@@ -51,9 +67,10 @@ fn marker_command(marker: &str, log: &Path) -> String {
} }
/// Lays out a config dir with a dry_run model, global agent.* hooks that /// Lays out a config dir with a dry_run model, global agent.* hooks that
/// append one marker line per event to `log`, a `probe-macro` agent that /// append one marker line per event to that event's marker file, a
/// whitelists everything, and a `probe` macro with the given YAML body. /// `probe-macro` agent that whitelists everything, and a `probe` macro with
fn write_fixture(dir: &Path, log: &Path, macro_yaml: &str) { /// the given YAML body.
fn write_fixture(dir: &Path, macro_yaml: &str) {
// Without IS_SANDBOX (scrubbed below) a run insists on a vault password // Without IS_SANDBOX (scrubbed below) a run insists on a vault password
// file, so the fixture provides one. // file, so the fixture provides one.
let vault_pass = dir.join("vault-pass"); let vault_pass = dir.join("vault-pass");
@@ -92,10 +109,10 @@ fn write_fixture(dir: &Path, log: &Path, macro_yaml: &str) {
\x20 - name: mark\n\ \x20 - name: mark\n\
\x20 command: '{interrupted}'\n", \x20 command: '{interrupted}'\n",
vault_pass = vault_pass.display(), vault_pass = vault_pass.display(),
started = marker_command("STARTED", log), started = marker_command("STARTED", dir),
completed = marker_command("COMPLETED", log), completed = marker_command("COMPLETED", dir),
failed = marker_command("FAILED", log), failed = marker_command("FAILED", dir),
interrupted = marker_command("INTERRUPTED", log), interrupted = marker_command("INTERRUPTED", dir),
), ),
) )
.unwrap(); .unwrap();
@@ -130,53 +147,71 @@ fn run_coyote(dir: &Path, args: &[&str]) -> Output {
.unwrap() .unwrap()
} }
/// Counts `marker`'s exact-match lines in its own marker file; a missing
/// file is zero fires. Matching stays byte-exact on both platforms because
/// `lines()` strips the CRLF that cmd's echo emits on Windows.
fn marker_count(dir: &Path, marker: &str) -> usize {
fs::read_to_string(marker_log(dir, marker))
.unwrap_or_default()
.lines()
.filter(|line| *line == marker)
.count()
}
fn dump_markers(dir: &Path) -> String {
MARKERS
.iter()
.map(|marker| {
let contents = fs::read_to_string(marker_log(dir, marker)).unwrap_or_default();
format!("{marker}: {contents:?}")
})
.collect::<Vec<_>>()
.join(", ")
}
/// Bounded poll until every expected marker is present. The binary's exit /// Bounded poll until every expected marker is present. The binary's exit
/// drain only acknowledges that each hook process SPAWNED — the hooks /// drain only acknowledges that each hook process SPAWNED — the hooks
/// themselves keep running concurrently after `output()` returns, and /// themselves keep running concurrently after `output()` returns, and
/// nothing orders their writes (the STARTED writer can land after the /// nothing orders their writes (the STARTED writer can land after the
/// terminal one). Waiting on all expected markers, not just the terminal /// terminal one). Waiting on all expected markers, not just the terminal
/// one, keeps the exact-count assertions below race-free. Marker matching /// one, keeps the exact-count assertions below race-free.
/// stays byte-exact on both platforms because `lines()` strips the CRLF fn wait_for_markers(dir: &Path, needles: &[&str]) {
/// that cmd's echo emits on Windows.
fn wait_for_markers(log: &Path, needles: &[&str]) -> String {
let deadline = Instant::now() + Duration::from_secs(10); let deadline = Instant::now() + Duration::from_secs(10);
loop { loop {
let contents = fs::read_to_string(log).unwrap_or_default(); if needles.iter().all(|needle| marker_count(dir, needle) > 0) {
if needles return;
.iter()
.all(|needle| contents.lines().any(|line| line == *needle))
{
return contents;
} }
assert!( assert!(
Instant::now() < deadline, Instant::now() < deadline,
"timed out waiting for {needles:?}; log so far: {contents:?}" "timed out waiting for {needles:?}; markers so far: {}",
dump_markers(dir)
); );
thread::sleep(Duration::from_millis(50)); thread::sleep(Duration::from_millis(50));
} }
} }
fn assert_marker_count(contents: &str, marker: &str, expected: usize) { fn assert_marker_count(dir: &Path, marker: &str, expected: usize) {
let count = contents.lines().filter(|line| *line == marker).count(); let count = marker_count(dir, marker);
assert_eq!( assert_eq!(
count, expected, count,
"expected {expected}x {marker}: {contents:?}" expected,
"expected {expected}x {marker}; markers so far: {}",
dump_markers(dir)
); );
} }
fn assert_started_and_single_terminal(contents: &str, terminal: &str) { fn assert_started_and_single_terminal(dir: &Path, terminal: &str) {
assert_marker_count(contents, "STARTED", 1); assert_marker_count(dir, "STARTED", 1);
for marker in ["COMPLETED", "FAILED", "INTERRUPTED"] { for marker in ["COMPLETED", "FAILED", "INTERRUPTED"] {
let expected = usize::from(marker == terminal); let expected = usize::from(marker == terminal);
assert_marker_count(contents, marker, expected); assert_marker_count(dir, marker, expected);
} }
} }
fn probe_macro_run(label: &str, macro_yaml: &str, args: &[&str], expect_success: bool) -> String { fn probe_macro_run(label: &str, macro_yaml: &str, args: &[&str], expect_success: bool) {
let dir = fresh_config_dir(label); let dir = fresh_config_dir(label);
let _cleanup = TempDirGuard(dir.clone()); let _cleanup = TempDirGuard(dir.clone());
let log = dir.join("agent-events.log"); write_fixture(&dir, macro_yaml);
write_fixture(&dir, &log, macro_yaml);
let output = run_coyote(&dir, args); let output = run_coyote(&dir, args);
assert_eq!( assert_eq!(
@@ -193,9 +228,8 @@ fn probe_macro_run(label: &str, macro_yaml: &str, args: &[&str], expect_success:
} else { } else {
"FAILED" "FAILED"
}; };
let contents = wait_for_markers(&log, &["STARTED", terminal]); wait_for_markers(&dir, &["STARTED", terminal]);
assert_started_and_single_terminal(&contents, terminal); assert_started_and_single_terminal(&dir, terminal);
contents
} }
#[test] #[test]