diff --git a/.config/nextest.toml b/.config/nextest.toml new file mode 100644 index 0000000000..b67af0bb8c --- /dev/null +++ b/.config/nextest.toml @@ -0,0 +1,25 @@ +# Nextest configuration. +# +# The single rule here concerns the `buzz-acp` tests that assert on wall-clock +# idle/deadline windows while a **real shell process** feeds them stdout. On +# Windows every `sleep` inside a fixture is a process spawn, and under full +# parallelism that shell competes with ~690 other tests for cores: a nominal +# `sleep 0.05` between two fixture lines was measured at 107 ms mean / 194 ms +# worst case during a full run, with outliers past 800 ms under heavier load. +# +# Two dead ends were measured before landing on retries (2026-08-01, buzz#83): +# +# • Widening the windows until they absorb the worst case stops the tests from +# ever going red for a real regression — the assertion would then only prove +# that the machine is not on fire. +# • `threads-required = "num-test-threads"` (run them alone) made it *worse*: +# suite runtime went 18 s → 110 s and the failure count went up, because the +# exclusive tests bunch up at the front and their `sleep 10` tails dominate. +# +# Retries fit what this actually is: a scheduling artefact, not a defect. A test +# that passes on any attempt was starved, not broken; a genuine regression fails +# all four attempts and still turns the suite red. + +[[profile.default.overrides]] +filter = 'package(buzz-acp) and test(/(idle_resets_on_stdout_activity|keepalive_resets_idle_past_deadline|steer_success_renews_hard_deadline_and_survives_past_original|acp_steer_injected_renews_hard_deadline_and_survives_past_original|acp_steer_started_new_turn_acks_success_without_renewing_hard_deadline|acp_steer_failed_outcome_acks_outcome_rejected|acp_steer_missing_outcome_acks_outcome_rejected_and_never_drops_event|acp_steer_request_omits_expected_run_id_and_carries_session_and_prompt|agent_exit_detected_as_eof)/)' +retries = 3 diff --git a/.empire/AGENTS.md b/.empire/AGENTS.md index c4977e96c4..c4b60dd5fc 100644 --- a/.empire/AGENTS.md +++ b/.empire/AGENTS.md @@ -1401,3 +1401,60 @@ Reihenfolge im Ablauf ist bindend: **erst die Vorwoche lesen, dann diese Woche s | Echter Lauf, drei Transporte | Kanal `#general` (Event `cf7285c0112e5e4c`), Telegram `message_id 114`, Tagesnotiz-Zeile | **Befund fürs Lagebild, nicht fürs Ritual:** owner-weit existiert genau **ein** offenes `ready`-P1-money. Ein Vorschlagsblock, der deshalb einzeilig bleibt, sieht aus wie ein Fehler — er wird sichtbar mit den ältesten `ready`-P1 aufgefüllt und die Herkunft je Zeile benannt (`[💶P1-money]` / `[P1]`). Aufgefüllt wird nur, nie ersetzt. + +--- + +## buzz-acp-Testsuite auf Windows (buzz#83) — drei Ursachen, keine davon ein Produktionsfehler + +Ausgangslage: `cargo nextest run -p buzz-acp --no-fail-fast` → **9 rote Tests**, dauerhaft. Eine Suite, die immer rot ist, beweist nichts mehr — jeder Rust-Ticket-Agent musste vorher per `git stash` gegenmessen, ob *seine* Änderung die Ursache war. + +### Ursache 1 — `bash` ist auf Windows die WSL-Bash (7 der 9 Tests) + +Die Fixtures spawnen den **bloßen Namen** `"bash"`. Der wird über den **Windows**-`PATH` aufgelöst, und dort gewinnt `C:\Windows\System32\bash.exe` — der WSL-Starter — gegen Git Bash, **auch wenn der Testlauf selbst aus Git Bash kommt**. WSL führt das Script in der Distro aus und reicht die anonyme Pipe des Elternprozesses nie durch: jedes `read` bekommt sofort EOF, das Script antwortet nicht, der Client meldet `AgentExited`. + +Bewiesen, nicht vermutet — `uname -sr` aus dem Fixture heraus: + +``` +DIAG start uname=[Linux 6.6.87.2-microsoft-standard-WSL2] pwd=[/mnt/c/...] +DIAG read1 rc=1 len=0 +``` + +Fix: `test_shell()` löst deterministisch auf — `BUZZ_TEST_BASH` → Git-Bash-`EXEPATH` → bekannte Installationspfade. **Kein Fallback auf `"bash"`**: das wäre wieder WSL, und ein fehlender Toolchain-Fund soll als klarer Panic auffallen statt als rätselhaftes `AgentExited`. + +> Dieselbe Falle steckt latent in `crates/buzz-relay/src/api/git/policy.rs` und `crates/buzz-acp/src/pool.rs` — dort laufen die Scripts heute nur als `sleep 10`, brauchen also kein stdin und überleben WSL zufällig. Wer dort ein `read` ergänzt, fällt sofort hinein. + +### Ursache 2 — `Path::display()` in einem Shell-Script (die Müll-Dateien im Repo) + +`spawn_steer_capture_script` interpolierte den Capture-Pfad **unquoted** ins Script. Auf Windows liefert `display()` `C:\Users\…`, bash frisst die Backslashes als Escapes und schreibt eine Datei namens `C:UsersrescueAppDataLocalTemp…json` — ins **aktuelle Verzeichnis**, und das ist unter `cargo test` das Crate-Root. Genau daher kamen die fünf Fremdkörper in `crates/buzz-acp/`. + +Fix: `script_path()` (Backslash → Slash) plus einfache Anführungszeichen im Script. Danach landen die Captures wieder in `%TEMP%\buzz-acp-steer-capture\` und `git status` bleibt nach dem Lauf sauber. + +### Ursache 3 — Zeitfenster, die kleiner sind als der Windows-Prozess-Start + +`idle_resets_on_stdout_activity` und `keepalive_resets_idle_past_deadline` messen Idle-Fenster von 200 ms bzw. 100 ms, während ein echter Shell-Prozess die Zeilen liefert. Auf Windows ist **jedes `sleep` im Fixture ein Prozess-Start**. Gemessen während eines vollen 697-Test-Laufs: Abstand zweier Fixture-Zeilen **107 ms im Mittel, 194 ms im schlechtesten Fall** für ein nominelles `sleep 0.05` — die alten Fenster lagen *innerhalb* dieser Streuung. Deshalb liefen die Tests einzeln grün und unter Last rot. + +Drei Maßnahmen, jede mit Begründung: +1. `spawn_script_ready()` — das Fixture sendet einen Ready-Marker, der Test startet seine Uhr erst danach. Vorher maß er den Shell-Start mit. +2. `IDLE_WINDOW = 800 ms` (~4× über dem gemessenen Worst Case) und `$(seq …)` → `for ((…))`, das spart einen Prozess-Start je Test. +3. `.config/nextest.toml`: `retries = 3` für die wanduhr-abhängigen Tests. + +**Zwei gemessene Sackgassen, damit sie niemand nochmal geht:** +- *Fenster einfach weit genug aufziehen* nimmt den Tests die Fähigkeit, für eine echte Regression rot zu werden — die Zusicherung beweist dann nur noch, dass die Maschine nicht brennt. +- *`threads-required = "num-test-threads"`* (Tests allein laufen lassen) machte es **schlimmer**: Suite-Laufzeit 18 s → 110 s und mehr Fehlschläge, weil sich die exklusiven Tests vorn stapeln und ihre `sleep 10`-Ausläufer den Lauf dominieren. + +Retries passen zu dem, was das ist: ein Scheduling-Artefakt, kein Defekt. Ein Test, der in irgendeinem Versuch grün wird, war ausgehungert; eine echte Regression fällt in allen vier Versuchen um. + +### ⚠️ Neue Worktree-Falle: geteiltes `CARGO_TARGET_DIR` serviert alte Binaries + +Um den Kompilier-Aufwand zu sparen, lief die Verifikation zuerst mit `CARGO_TARGET_DIR` auf das `target/` des Haupt-Checkouts. Zwei Läufe waren grün, der dritte meldete plötzlich **676 statt 697 Tests**, exakt die Fehler von *vor* dem Fix und die längst reparierten Müll-Dateien wieder im Baum: cargo hatte ein Artefakt des Haupt-Checkouts wiederverwendet. **Ein Worktree bekommt sein eigenes Target-Verzeichnis** — sonst misst man irgendwann den Stand eines anderen Branches und hält ihn für den eigenen. + +### Beweisstand (2026-08-01) + +| Prüfung | Ergebnis | +|---|---| +| Ausgangslage `cargo nextest run -p buzz-acp --no-fail-fast` | 697 Tests, **9 failed** | +| Nach Ursache 1 + 2 | **2 failed** (nur noch die Zeitfenster) | +| Nach Ursache 3, eigenes Target-Verzeichnis | **697 passed, 0 failed** | +| Wiederholbarkeit | drei aufeinanderfolgende Läufe grün (`1 flaky` = Retry gegriffen, kein Fehlschlag) | +| `git status --short` nach dem Lauf | keine neuen untracked Dateien | +| Rot-Probe | Fixture-Antwort verfälscht → **genau** der zugehörige Test rot, Rest grün | diff --git a/crates/buzz-acp/src/acp.rs b/crates/buzz-acp/src/acp.rs index 46aecff2e6..9922aa9b84 100644 --- a/crates/buzz-acp/src/acp.rs +++ b/crates/buzz-acp/src/acp.rs @@ -2956,12 +2956,117 @@ mod tests { ); } + /// Resolve the POSIX shell the fixture scripts run in. + /// + /// Spawning the bare name `"bash"` resolves through the **Windows** `PATH`, + /// where `C:\Windows\System32\bash.exe` — the WSL launcher — normally wins + /// over Git Bash even when the test itself was started from Git Bash. WSL + /// runs the script inside the distro and never hands it the parent's + /// anonymous pipe: every `read` in the fixture returns EOF immediately, the + /// script answers nothing, and the client reports `AgentExited`. + /// + /// Measured 2026-08-01 by printing `uname -sr` from inside a fixture: + /// `Linux 6.6.87.2-microsoft-standard-WSL2`, `pwd` = `/mnt/c/...`. + /// + /// Override with `BUZZ_TEST_BASH` when neither heuristic finds a usable + /// shell. On unix the bare name is correct and stays. + #[cfg(windows)] + fn test_shell() -> String { + if let Ok(explicit) = std::env::var("BUZZ_TEST_BASH") { + if !explicit.is_empty() { + return explicit; + } + } + // Git Bash exports EXEPATH (its install root) into every shell it starts. + if let Ok(exepath) = std::env::var("EXEPATH") { + let candidate = std::path::Path::new(&exepath).join("bin").join("bash.exe"); + if candidate.is_file() { + return candidate.to_string_lossy().into_owned(); + } + } + for candidate in [ + r"C:\Program Files\Git\bin\bash.exe", + r"C:\Program Files (x86)\Git\bin\bash.exe", + ] { + if std::path::Path::new(candidate).is_file() { + return candidate.to_string(); + } + } + // Deliberately NOT falling back to "bash": that is the broken WSL path + // and would turn a missing-toolchain error into a silent hang-and-fail. + panic!( + "no Git Bash found for fixture scripts — set BUZZ_TEST_BASH to a \ + POSIX shell that inherits stdin (NOT System32\\bash.exe, which is WSL)" + ); + } + + #[cfg(not(windows))] + fn test_shell() -> String { + "bash".to_string() + } + + /// Render a path for use *inside* a fixture script. + /// + /// `Path::display()` yields `C:\Users\…` on Windows. Interpolated into a + /// shell script that is a redirect target, bash strips the backslashes and + /// writes a file literally named `C:UsersrescueAppData…json` into the + /// current directory — which is the crate root under `cargo test`. That is + /// where the stray files in `crates/buzz-acp/` came from. + fn script_path(path: &std::path::Path) -> String { + path.display().to_string().replace('\\', "/") + } + async fn spawn_script(script: &str) -> AcpClient { - AcpClient::spawn("bash", &["-c".into(), script.into()], &[], false) + AcpClient::spawn(&test_shell(), &["-c".into(), script.into()], &[], false) .await .expect("failed to spawn test script") } + /// Spawn a fixture and return only once the shell has actually started. + /// + /// `AcpClient::spawn` returns as soon as the process handle exists — the + /// shell may still be loading. Idle-window tests start their clock right + /// after and therefore measure **shell startup**, not the behaviour under + /// test: the idle timer expires before the script has written its first + /// line, and the test sees a timeout it never provoked. + /// + /// Measured 2026-08-01: `idle_resets_on_stdout_activity` and + /// `keepalive_resets_idle_past_deadline` pass in isolation and fail in the + /// full 697-test run after ~0.6 s — Windows process startup crosses their + /// 100–200 ms idle window once nextest saturates the cores. + /// + /// The script gets a leading ready marker; this drains it, so the timer + /// starts against a shell that has demonstrably produced output. The marker + /// is a `session/update` notification because idle-reset only counts valid + /// JSON notifications — anything else would change what the test measures. + /// Idle window for the two tests that assert on idle-timer resets. + /// + /// Not a guess: the gap between two fixture messages was measured on this + /// Windows host during a full 697-test nextest run — mean **107 ms**, worst + /// case **194 ms** for a nominal `sleep 0.05`. Every `sleep` is a real + /// process spawn under MSYS, so the shell sets the pace, not the sleep. + /// The old 100/200 ms windows sat *inside* that spread, which is exactly + /// why both tests passed alone and failed under load. 800 ms keeps ~4× + /// headroom over the measured worst case and stays far below the 10 s hard + /// deadline, so the assertions can still go red for a real regression. + const IDLE_WINDOW: std::time::Duration = std::time::Duration::from_millis(800); + + async fn spawn_script_ready(script: &str) -> AcpClient { + const READY: &str = r#"{"jsonrpc":"2.0","method":"session/update","params":{"update":{"sessionUpdate":"testReady"}}}"#; + let mut client = spawn_script(&format!("printf '%s\\n' '{READY}'\n{script}")).await; + let line = client + .reader + .next() + .await + .expect("fixture produced no ready marker") + .expect("fixture stdout was not readable"); + assert!( + line.contains("testReady"), + "first fixture line must be the ready marker, got: {line}" + ); + client + } + /// Spawn a probe script whose file name carries a runtime identity (e.g. /// `hermes-acp`) and return the value of `var` as the child observed it. /// `` means the child did not receive the var. @@ -3100,26 +3205,27 @@ mod tests { async fn idle_resets_on_stdout_activity() { // Send valid JSON (session/update notifications) to reset the idle timer. // Non-JSON lines no longer reset idle — only valid JSON notifications do. - let mut client = spawn_script( - r#"for i in $(seq 1 10); do echo '{"jsonrpc":"2.0","method":"session/update","params":{"update":{"sessionUpdate":"agent_thought_chunk","content":{"text":"thinking"}}}}'; sleep 0.05; done; sleep 10"#, + // `for ((...))` instead of `$(seq …)`: every subshell is a real Windows + // process spawn, and the gap between messages is what this measures. + let mut client = spawn_script_ready( + r#"for ((i=0;i<20;i++)); do echo '{"jsonrpc":"2.0","method":"session/update","params":{"update":{"sessionUpdate":"agent_thought_chunk","content":{"text":"thinking"}}}}'; sleep 0.05; done; sleep 10"#, ) .await; let max_dur = std::time::Duration::from_secs(10); let hard_deadline = tokio::time::Instant::now() + max_dur; let start = std::time::Instant::now(); let result = client - .read_until_response_with_idle_timeout( - "test", - 999, - std::time::Duration::from_millis(200), - hard_deadline, - max_dur, - ) + .read_until_response_with_idle_timeout("test", 999, IDLE_WINDOW, hard_deadline, max_dur) .await; let elapsed = start.elapsed(); - // 10 messages × 50ms = ~500ms of activity, then idle timeout fires after 200ms more - assert!(elapsed >= std::time::Duration::from_millis(400)); - assert!(elapsed < std::time::Duration::from_secs(3)); + // 20 messages at a measured ~107 ms apart = ~2.1 s of activity, i.e. + // more than two idle windows. Without the reset the loop would end + // after a single window (~0.8 s) — the lower bound can still go red. + assert!( + elapsed >= std::time::Duration::from_millis(1200), + "activity must reset the idle timer past a single window; elapsed only {elapsed:?}" + ); + assert!(elapsed < std::time::Duration::from_secs(9)); assert!(matches!(result, Err(AcpError::IdleTimeout(_)))); } @@ -3295,32 +3401,26 @@ mod tests { #[tokio::test] async fn keepalive_resets_idle_past_deadline() { - // Keepalive session/update lines every 50ms against a 100ms idle deadline. - // The turn should survive well past the 100ms deadline (proves the fix). - let mut client = spawn_script( - r#"for i in $(seq 1 20); do echo '{"jsonrpc":"2.0","method":"session/update","params":{"update":{"sessionUpdate":"keepalive"}}}'; sleep 0.05; done; sleep 10"#, + // Keepalive session/update lines against a shorter idle deadline. + // The turn must survive well past that deadline (proves the fix). + let mut client = spawn_script_ready( + r#"for ((i=0;i<20;i++)); do echo '{"jsonrpc":"2.0","method":"session/update","params":{"update":{"sessionUpdate":"keepalive"}}}'; sleep 0.05; done; sleep 10"#, ) .await; let max_dur = std::time::Duration::from_secs(10); let hard_deadline = tokio::time::Instant::now() + max_dur; let start = std::time::Instant::now(); let result = client - .read_until_response_with_idle_timeout( - "test", - 999, - std::time::Duration::from_millis(100), - hard_deadline, - max_dur, - ) + .read_until_response_with_idle_timeout("test", 999, IDLE_WINDOW, hard_deadline, max_dur) .await; let elapsed = start.elapsed(); - // 20 keepalives × 50ms = ~1000ms of activity, then idle fires after 100ms more. - // Must survive well past the 100ms deadline. + // 20 keepalives at a measured ~107 ms apart = ~2.1 s of activity, i.e. + // more than two idle windows — well past a single deadline. assert!( - elapsed >= std::time::Duration::from_millis(500), + elapsed >= std::time::Duration::from_millis(1200), "keepalive should reset idle past the deadline; elapsed only {elapsed:?}" ); - assert!(elapsed < std::time::Duration::from_secs(5)); + assert!(elapsed < std::time::Duration::from_secs(9)); assert!(matches!(result, Err(AcpError::IdleTimeout(_)))); } @@ -3865,9 +3965,9 @@ mod tests { response: &str, ) -> AcpClient { let script = format!( - "read -r line; printf '%s' \"$line\" > {capture}; \ + "read -r line; printf '%s' \"$line\" > '{capture}'; \ printf '%s\\n' '{response}'; sleep 10", - capture = capture_path.display(), + capture = script_path(capture_path), response = response, ); spawn_script(&script).await