diff --git a/tests/macro_bracketing.rs b/tests/macro_bracketing.rs index 5f65010..b079930 100644 --- a/tests/macro_bracketing.rs +++ b/tests/macro_bracketing.rs @@ -15,6 +15,8 @@ use std::process::{Command, Output, Stdio}; use std::thread; use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; +const MARKERS: [&str; 4] = ["STARTED", "COMPLETED", "FAILED", "INTERRUPTED"]; + fn fresh_config_dir(label: &str) -> PathBuf { let unique = SystemTime::now() .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 -/// 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, log: &Path) -> String { +/// Path of the file `marker`'s hook appends to. Every event gets its OWN +/// file because cmd opens `>>` targets write-exclusive (no shared write +/// access): the STARTED and terminal hook children run concurrently, and +/// when both appended to one shared log, overlapping opens made the loser +/// fail with a sharing violation and silently drop its line — a permanent +/// marker loss that surfaced as a Windows-CI-only flake. Separate files +/// 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(); if cfg!(windows) { 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 -/// append one marker line per event to `log`, a `probe-macro` agent that -/// whitelists everything, and a `probe` macro with the given YAML body. -fn write_fixture(dir: &Path, log: &Path, macro_yaml: &str) { +/// append one marker line per event to that event's marker file, a +/// `probe-macro` agent that whitelists everything, and a `probe` macro with +/// the given YAML body. +fn write_fixture(dir: &Path, macro_yaml: &str) { // Without IS_SANDBOX (scrubbed below) a run insists on a vault password // file, so the fixture provides one. 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 command: '{interrupted}'\n", vault_pass = vault_pass.display(), - started = marker_command("STARTED", log), - completed = marker_command("COMPLETED", log), - failed = marker_command("FAILED", log), - interrupted = marker_command("INTERRUPTED", log), + started = marker_command("STARTED", dir), + completed = marker_command("COMPLETED", dir), + failed = marker_command("FAILED", dir), + interrupted = marker_command("INTERRUPTED", dir), ), ) .unwrap(); @@ -130,53 +147,71 @@ fn run_coyote(dir: &Path, args: &[&str]) -> Output { .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::>() + .join(", ") +} + /// Bounded poll until every expected marker is present. The binary's exit /// drain only acknowledges that each hook process SPAWNED — the hooks /// themselves keep running concurrently after `output()` returns, and /// nothing orders their writes (the STARTED writer can land after the /// terminal one). Waiting on all expected markers, not just the terminal -/// one, keeps the exact-count assertions below race-free. Marker matching -/// stays byte-exact on both platforms because `lines()` strips the CRLF -/// that cmd's echo emits on Windows. -fn wait_for_markers(log: &Path, needles: &[&str]) -> String { +/// one, keeps the exact-count assertions below race-free. +fn wait_for_markers(dir: &Path, needles: &[&str]) { let deadline = Instant::now() + Duration::from_secs(10); loop { - let contents = fs::read_to_string(log).unwrap_or_default(); - if needles - .iter() - .all(|needle| contents.lines().any(|line| line == *needle)) - { - return contents; + if needles.iter().all(|needle| marker_count(dir, needle) > 0) { + return; } assert!( 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)); } } -fn assert_marker_count(contents: &str, marker: &str, expected: usize) { - let count = contents.lines().filter(|line| *line == marker).count(); +fn assert_marker_count(dir: &Path, marker: &str, expected: usize) { + let count = marker_count(dir, marker); assert_eq!( - count, expected, - "expected {expected}x {marker}: {contents:?}" + count, + expected, + "expected {expected}x {marker}; markers so far: {}", + dump_markers(dir) ); } -fn assert_started_and_single_terminal(contents: &str, terminal: &str) { - assert_marker_count(contents, "STARTED", 1); +fn assert_started_and_single_terminal(dir: &Path, terminal: &str) { + assert_marker_count(dir, "STARTED", 1); for marker in ["COMPLETED", "FAILED", "INTERRUPTED"] { 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 _cleanup = TempDirGuard(dir.clone()); - let log = dir.join("agent-events.log"); - write_fixture(&dir, &log, macro_yaml); + write_fixture(&dir, macro_yaml); let output = run_coyote(&dir, args); assert_eq!( @@ -193,9 +228,8 @@ fn probe_macro_run(label: &str, macro_yaml: &str, args: &[&str], expect_success: } else { "FAILED" }; - let contents = wait_for_markers(&log, &["STARTED", terminal]); - assert_started_and_single_terminal(&contents, terminal); - contents + wait_for_markers(&dir, &["STARTED", terminal]); + assert_started_and_single_terminal(&dir, terminal); } #[test]