Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 25 additions & 0 deletions .config/nextest.toml
Original file line number Diff line number Diff line change
@@ -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
57 changes: 57 additions & 0 deletions .empire/AGENTS.md
Original file line number Diff line number Diff line change
Expand Up @@ -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 |
160 changes: 130 additions & 30 deletions crates/buzz-acp/src/acp.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
/// `<unset>` means the child did not receive the var.
Expand Down Expand Up @@ -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(_))));
}

Expand Down Expand Up @@ -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(_))));
}

Expand Down Expand Up @@ -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
Expand Down
Loading