2 Commits

Author	SHA1	Message	Date
Ignacy Łątka	f79e53a6e3	test(tool-server): scope vega-cli-timeout sentinels to the running process (#711) ... ## Problem `vega-cli-timeout.test.ts` fails intermittently, always the same two tests, always the same way: ``` rejects on its own deadline when the CLI never returns → expected { stdout: '', stderr: '' } to be an instance of Error reaps the ENTIRE worker tree on timeout → promise resolved "{ stdout: '', stderr: '' }" instead of rejecting ``` Both at **~60-130 ms against a 400 ms deadline** — `runVega` *resolved* rather than timing out. It never fails in isolation. ## Not a tight budget, and not a reaping race | condition | failures | |---|---| | isolated, 20 runs | 0/20 | | under a parallel full-suite run, 15 runs | **2/15** | | pinned to one CPU (`taskset -c 0`), 8 runs | 0/8 | The single-CPU pin is the discriminator: if the 400 ms budget were too tight, or the reap raced under contention, starving it to one core would make it worse. It passes 8/8. `packages/tool-server/src/utils/vega-cli.ts` is **not** implicated and is unchanged here. ## Cause: the sentinel namespace is machine-global The test's worker sentinels were fixed constants (`sleep 69101` … `sleep 69107`), and cleanup matches them with `pkill -f` / `pgrep -f` — which are **global to the machine, not scoped to the process**. Two concurrent runs of this file therefore share one namespace, and each run's `afterEach` `pkill`s the *other* run's live workers. The fake `vega` launcher's blocking `spawnSync("sleep", …)` returns early, the launcher exits 0, and `runVega` resolves cleanly well inside its deadline — exactly the observed signature. The existing comment shows the pattern was already narrowed once (*"Match only this suite's sentinels (6910[0-9]) rather than a loose `sleep 691`"*). That tightened it against other suites but not against a second copy of this suite, which is the case that actually occurs: CI matrices, `vitest --no-file-parallelism` reruns, and any machine running more than one checkout. ## Deterministic reproduction A neighbour issuing this file's own sweep (`pkill -f '^sleep 6910[0-9]$'`) on a 20 Hz loop reproduces it **every time**: ``` before → Tests 2 failed | 7 passed (9) (3/3 rounds, both named tests) after → Tests 12 passed (12) (3/3 rounds, same neighbour live) ``` ## Fix Derive the sentinels from a per-process tag (pid plus three random digits) and scope every `pgrep`/`pkill` to it. Two live processes cannot share a pid, so two concurrent runs never collide; the random digits cut the leftover case — a worker leaked by an earlier run whose pid has since been recycled — to 1/1000. A concurrent run computes a different tag and its sweeps no longer reach these workers. The tag rides in the *fractional* part of the sleep duration, which also shortens a leaked worker's life from ~19 h to 10 min. That matters more than it looks: previously a later run of this file would clean up an abandoned worker as a side effect of the shared namespace, and scoping the namespace deliberately removes that accident. The same investigation turned up three more problems in the file, and the rest of the diff is those: - **Regressions reported a bare timeout.** Several tests here outrun vitest's 5s default - the delayed-close test's own deadline is 10s - so a real failure printed `Test timed out in 5000ms` and named nothing. The file now sets its own 20s budget; `beforeAll` carries an explicit one because a hook resolves its budget when it is registered. - **Four assertions could pass with nothing to assert against.** `waitForClear` reads 0 just as readily for a worker that never spawned, so both reap tests observe their workers alive first, and `strayCount` returns -1 rather than 0 when it cannot look at all. The two output-cap reaps have no such window (#841). - **The reap test's premise was unasserted.** It is named for a worker that escaped the launcher's process group, but nothing checked that it had: with the observation below removed, dropping `detached: true` from the `hang` fake leaves every test green, and with that fixture the descendant sweep could be deleted from `reapVegaGroup` with everything still green. One polled sample - a single `ps`, so the count and the groups cannot disagree about the instant they describe - now returns both, so dropping the flag fails with `{ workers: 2, groups: 1 }` — naming which half broke — while deleting the sweep still fails with `expected 1 to be +0`. Smaller, each covered below: the near-deadline `timeoutMs` 600 -> 900ms, now sharing one const with the bound that pins it; the reap deadline 400ms -> 4s, to give the launcher room to spawn both workers before the reap ends the observation window; a `beforeAll` warm-up that absorbs macOS's first-exec penalty; and three added tests (sweep positive control, random-block width, longer-pid decoy). Three comments about production behaviour were corrected too - the header's account of which mechanism reaps which worker, the reap test's on what the descendant sweep covers by itself, and the fake's on what reaps the launcher's own sleep. ## Verification - Deterministic repro above, before and after, same neighbour process. - **Teeth check** — a sweeper matching the post-fix *shape* but ignoring the tag (`^sleep 600\.[0-9]+$`) still kills the fixed code 4/4. The workers remain real and killable; only the tag protects them, so the fix is not passing by making them unmatchable. - **Vacuity check** — mutating the source (`collectDescendantPids` → `[]`) makes `strayCount` report a live stray (`expected 1 to be +0`), proving the new escaped `pgrep` pattern genuinely matches. - **Mutation** — pinning `RUN_TAG` to a constant, with a neighbour using the pattern a concurrent run of the *mutated* file computes: 4/4 fail. It now takes down four tests, not the two originally named — the two observations this PR adds, the near-deadline elapsed bound and the drain count, are killed by the same neighbour. - **Positive control** — every reap assertion here reads `waitForClear(...) === 0`, which is also what `strayCount` returns when the pattern matches nothing, so the suite passed with a pattern that matched nothing. Two of the three `sentinel bookkeeping` tests require a count of 1 first, and the drain reap counts its worker before the reap; the timeout reap counts through `ps` instead, so it is the bookkeeping tests that stand behind it here. Neutering `cmdlinePattern` fails those three (`expected +0 to be 1`), neutering `sweep()` fails one (`expected 1 to be +0`); the rest stay green in both cases. - **The workers under test are the ones observed** — giving only the fake launcher's `hang` workers a sentinel `strayCount` cannot see leaves the whole suite green without the counts, and fails `{ workers: +0, groups: +0 }` against `{ workers: 2, groups: 2 }` with them. Same for the drain path. The two overflow tests keep no count, and are therefore **not** pinned: breaking only the `flood` branch's sentinel leaves all 12 green. Their reap fires within ~20-100ms of the spawn, so an observation taken after the call never catches it (0/8), and one taken concurrently loses the race about a third of the time under load. Filed as #841, which records a non-racy alternative. - **Each observation is budgeted off the call it watches** — a poll shorter than that call turns a slow launcher start into a failed observation (`expected +0 to be 1` on the drain path, `{ workers: +0, groups: +0 }` on the reap) rather than into the reap it guards. The drain observation gets its call's whole 10s; the timeout reap's window is ended by the reap itself, so there the deadline *is* the budget, and it and the poll are both 4s. The reap observation's worst was 1485ms at 50-way concurrency against that 4s (2.7x); the drain observation's own worst was 1836ms against its 10s (5.5x). Stalling the `linger-grouped` branch 3.5s fails the drain observation on the 3s default poll and passes on the call's 10s; stalling `hang` 2.5s fails the reap observation on a 2s deadline, which kills the launcher mid-stall, and passes on 4s. The reap and drain observations are both new here, so the reap deadline is what the added runtime buys: that test goes from ~450ms on main to 4.13s, about 3.7s of the file's 4.4s increase. Measured against the branch's own intermediate 2s deadline the step is +1.95s idle (7.18 -> 9.13s) and +1.99s under load (10.52 -> 12.51s), and it takes that observation from 1.35x to 2.7x. The file's thinnest margin is the near-deadline row above, which no deadline change can widen. The drain-side change is free, since the poll returns as soon as the count matches. An interleaved A/B soak, 40 runs per arm at load 90-240, produced **no** failure of either observation in **either** arm, so it is neutral rather than confirming: the case rests on the injected stall and on the measured margins, not on a reproduced natural rate. - **Slot width is pinned** — `SentinelSlot` makes a 2-digit slot a compile error (`TS2345: Argument of type '10' is not assignable to parameter of type 'SentinelSlot'`). A 2-digit slot would both escape the sweep's `[0-9]` and break the equal-width argument the isolation rests on. - **The launcher is warmed in `beforeAll`** — the drain-grace test gives the launcher 900ms to start, and no larger value is available: it also has to stay under `VEGA_EXIT_DRAIN_GRACE_MS` (1000) to force the race at all. macOS charges the FIRST exec of a newly written file and nothing after it, and that cold exec does not fit — measured p90 1099ms / max 1684ms at 20-way concurrency under 92 hog processes, which made that test fail **38 of 60 (63%)** when run on its own. It is not `node` starting: a fresh `#!/bin/sh` script shows the same jump, and warming `node` elsewhere leaves the solo rate at **55/60** - worse than not warming at all. Without the warm-up a whole-file run never saw it, because whichever tests run first pay the exec incidentally. Paying that cost once in `beforeAll` makes it invocation-independent: startup at that call site measured 136-148ms without the warm-up and 32-37ms with it. - **Margins, worst observed against budget** — across ~950 runs at up to 80-way concurrency under 92-132 hog processes (load avg 218-275): | wait | budget | worst observed | margin | |---|---|---|---| | near-deadline launcher start | 900ms | 700ms (80-way) | **1.29x** | | `elapsed < 5_000` (delayed close) | 5000ms | 3017ms | 1.66x | | worst `waitForClear` | 3000ms | 1648ms | 1.82x | | reap observation | 4000ms | 1485ms | 2.69x | | `elapsed < 2_500` (deadline) | 2500ms | 742ms | 3.37x | | slowest test vs `testTimeout` | 20_000ms | 4130ms (idle) | 4.84x | | drain observation | 10_000ms | 1836ms | 5.45x | The slowest-test row is an idle measurement, and a floor rather than a worst: the reap test's launcher never exits, so that test cannot settle before its own 4s deadline. The thinnest margin is structural, not tunable: that test's `timeoutMs` must clear the launcher's startup *and* stay under `VEGA_EXIT_DRAIN_GRACE_MS` (1000) for the race it forces to exist at all. Both bounds sit in that one sub-second band, so buying margin here spends it on the `toBeGreaterThan` bound below; the `beforeAll` warm-up is the only lever that does not. It still discriminates — dropping the exit path's `clearTimeout` fails it with `promise rejected "FailureError: vega linger ..." instead of resolving`. The `toBeGreaterThan(900)` bound on that same test sits at 1.11x but is safe by construction: the drain cannot fire before `grace` ms and scheduler delay only pushes it later, so load can never move it toward the bound. - **Considered and not taken: sweeping the eight exact sentinels** — replacing the `[0-9]` slot glob with an ERE alternation of the literal sentinels looks like it would drop the equal-width invariant and the two tests that pin it. It would not. `pkill -f` still matches every process on the machine, so isolation still rests on equal width: pid `1234` / rand `567` / a two-digit slot `11` spells `600.123456711`, byte-identical to pid `12345` / rand `671` / slot `1`, so the second run's alternation lists the first run's worker verbatim and kills it. The unpadded random block collides the same way (`1234`+`56`+`7` = `123`+`456`+`7`). `SentinelSlot`, the padding test and the `$` anchor are load-bearing under either form; only part of `cmdlinePattern`'s docblock would go. - **Deliberate idiom deviation, flag if you disagree** — `vi.setConfig` and `testTimeout` appear nowhere else in the repo; the convention here is a positional `it(..., 10_000)` (`boot-device-hardening.test.ts:214`) or `{ timeout: N }` (14 uses). Several tests in this file can exceed the 5s default, and two rounds of per-test budgeting each missed some, so the budget is set once for the file instead of enumerated per test. The wall-clock assertions (`elapsed < 2_500`, `< 5_000`) are unaffected — they assert speed directly rather than relying on the test budget. - **The wrapper self-match is real, but GNU-only** — `pgrep`'s own `sh -c "pgrep -f '<pattern>' || true"` wrapper carries the pattern in its argv. Verified in debian against procps-ng 4.0.2: a bare sentinel with no anchors returns **2** matches (the second being the wrapper), and `^`, `\.` or `$` alone each cut it to 1. On macOS it cannot be reproduced at all — BSD `pgrep` excludes its own ancestors — so the docblock says which platform the hazard belongs to. - **The `$` anchor is pinned** — a decoy shaped like a longer-pid run's sentinel must survive `sweep()`. Dropping `$` kills it (`expected +0 to be 1`). `^` is deliberately left unpinned: without it the pattern reaches only command lines ending in this run's unique tag, which nothing can produce. - **The slow-failing regressions stay legible** — tests here outrun vitest's 5s default on a runVega deadline of up to 10s, a 3s clearance poll, or both. Past 5s vitest reports `Test timed out in 5000ms` and names nothing, so the file raises its own budget with `vi.setConfig({ testTimeout: 20_000 })`. Measured, each with the matching production path disabled: the delayed-close test `Test timed out in 5000ms` @5029ms → `promise rejected "FailureError: vega linger …" instead of resolving` @10031ms; the flood test `Test timed out in 5000ms` @5059ms → `expected 'timeout' to be 'subprocess'` @5030ms; the reap test → `expected 1 to be +0` @7254ms. No regression in this file reports a bare vitest timeout any more. - Two simultaneous runs, 4 rounds: 8/8 green; 15 sequential and 15 concurrent-triple runs green, no strays. - `eslint` 0, `prettier --check` 0, `tsc -p tsconfig.test.json --noEmit` 0 — exit codes read directly. ## Sibling audit No other test identifies its workers by matching a pattern against the machine-wide process table — the only other `pkill`/`pgrep` invocation under `packages/` or `scripts/` is a research CLI (`argent-private/research/physical-ios/cli/argent-ios.ts:441`), which is not a test and owns no sentinel workers. Every candidate checked: `adb-terminal-error-format` (mocks `child_process`), `await-ui-element` / `await-screen-idle` / `mjpeg-stream` (in-process timers, no subprocess), `artifacts` (real `tar`, no deadline assertion), `list-devices` (`ps` mocked), `vega-process` (real `ps`, read-only, owns no workers), `launcher-helpers` (TCP, no subprocess). That is the narrow claim. The broader one — "the only test that spawns real workers into a global namespace under a deadline" — does **not** hold: `launcher-spawn`, `launcher-duplicate-spawn`, `launcher-version-gate` and `launcher-sweep` all spawn real long-lived servers (the first three through `spawnToolsServer`, so detached; `launcher-sweep` a plain `spawn`), and `launcher-spawn` asserts on elapsed time. They are safe for a reason worth stating, because it is the same principle as this fix: each redirects `HOME` to a `mkdtemp` dir, so their state directory is per-run. Several unrelated tests do share the defect and are filed separately, since none is in this diff: #835, #836, #837. The mutation sweep run over this suite also surfaced `runVega` behaviours its assertions do not pin: the signal-death `subprocess` classification (#845), `settle()` clearing the exit timer (#847), the output cap's UTF-8-byte semantics (#849), and both `destroy()` pairs (#850) each survive as a mutant through a fully green run, as does `VEGA_KILL_SIGNAL` softened to `SIGTERM` (#848). The process-group SIGKILL (#846) is caught, but incidentally and flakily - by the stderr-cap test, in 1 of 3 consecutive runs. All of these predate this PR: the nine tests that exercise `runVega` are the same nine on `main`, the three added here covering the sentinel helpers themselves.	2026-08-20 16:32:22 +02:00
Hubert Gancarczyk	6bc5376746	fix(tool-server): stop list-devices from hanging - wedged-VVD stall and CLI socket leak (#419) ... ## Summary `list-devices` (an `alwaysLoad` tool called at session start and frequently after) could appear to **hang**. Investigation found **two independent causes**, both fixed here: 1. **Server-side (Vega):** a wedged Vega VVD turned `list-devices` into a ~40s stall and leaked `vega` CLI subprocesses. 2. **Client-side (CLI):** every `argent run …` lingered a constant **~6s after it had already printed its result**, because a health-check `fetch` never drained its response body and kept an undici keep-alive socket ref'd until the server closed it. Net effect for `argent run list-devices`: **6.15s → 0.91s**, and the worst-case wedged-VVD stall drops from ~40s to a bounded short call. --- ## Problem 1 — wedged Vega VVD stalls `list-devices` (~40s) and leaks processes On a host with the Vega SDK installed and a **running-but-unresponsive VVD**, `list-devices`' Vega discovery path made **two serial 20s CLI calls** that both hung: - `vega device list` → SIGKILL at 20s - then (recovery) `vega device info` → SIGKILL at another 20s → **~40s total** Three compounding defects: - `execFileAsync` resolves on stdio **close**, not child **exit**. The `vega` launcher forks a `python3 → node → vda` worker tree; an orphaned worker holds the stdout pipe open, so the call stayed pending for the full timeout even after the launcher was killed. - The `device info` recovery fired even when `device list` had **hung**, doubling the cost and spawning a second hanging subprocess. - On timeout we killed only the **direct child**, so the `python3 → node → vda` worker tree was **orphaned, not reaped** — leaking a process tree per call (a wedged host had accumulated ~269 of them). ### Fix - **`runVega` (`vega-cli.ts`):** switched from `execFileAsync` to `spawn` with **`detached: true`**, making the launcher its own **process-group leader**, and on timeout SIGKILL the **whole process group** (`process.kill(-pid)`) — which reaps the entire `python3 → node → vda` tree, **not just the launcher**. We also destroy our stdio stream ends so a pipe-holding worker can't keep the call pending. (`execFile` silently drops `detached`, which is why the switch to `spawn` was required.) - **Success path doesn't depend on stdio EOF either:** we prefer `close` (fully drained), but if a grandchild holds the stdout pipe open after a **clean exit**, we fall back to `exit` + a short (~1s) drain grace and resolve with the captured output — so a finished call can't be stalled into the timeout and then rejected, discarding valid data. The output cap is measured in real UTF-8 bytes. For that guarantee to hold at the boundary, the `exit` handler **disarms the main timeout timer**: once the child has terminated the wall-clock deadline is moot, so a clean exit landing within the drain grace of the deadline resolves with its output instead of being mis-rejected as a `timeout` (which would also wrongly suppress the `listVegaDevices` recovery for a still-running VVD). - **Belt-and-suspenders for a worker that escapes the group:** an earlier investigation reported the worker tree `setsid()`-ing into its own session (which would defeat a group-only SIGKILL). To be safe regardless of which is true, on timeout we **snapshot the launcher's descendants from the process table *before* killing** (a setsid'd worker keeps its `ppid` pointing at the launcher until the launcher dies, so a `ppid` tree-walk still reaches it) and SIGKILL those pids individually after the group kill. The snapshot is **precise** — only this launcher's own descendants, by pid, so a concurrent `vega` call's workers are never touched — and bounded, and the group kill runs regardless of whether it succeeds. - A real-subprocess test confirms **0 orphans** after a timeout, including a worker deliberately spawned into its **own** process group (so the group kill alone cannot reach it — the test fails without the descendant sweep). - **`listVegaDevices` (`vega-devices.ts`):** skip the `device info` recovery only when `device list` **timed out** (a wedged agent — keyed off the failure's `error_kind: "timeout"`), so a hung list no longer pays for a second timeout wait. A *fast* (non-timeout) list failure still recovers a genuinely-running VVD rather than mis-reporting it as stopped. Tightened discovery timeouts (20s → 6s/4s — a generous multiple of the ~1s healthy time so a cold-start `vega` launcher isn't spuriously timed out, with their sum (10s) kept under the 15s branch deadline with margin). - **`list-devices.ts`:** added a 15s `withDeadline` backstop around the Android and Vega branches so no single branch can stall the whole fan-out (returns partial results + logs a note). Sized to sit ~5s above the Vega branch's ~10s worst case, so the backstop never truncates a slow-but-completing branch (which would drop a real device); an invariant test guards that ordering. - **`readAvdName` (`adb.ts`):** run the two `getprop` probes concurrently so a wedged emulator costs 5s, not 10s. --- ## Problem 2 — `argent run` hangs ~6s after printing output (CLI socket leak) Independent of Vega. The tool-server returns `list-devices` in <1s, but the CLI process took a **constant ~6s** to exit. Any path that calls `process.exit()` was instant; any path that returned naturally (`argent run …`, `argent run … --help`, `argent tools`) lingered ~6s. **Root cause:** `isToolsServerHealthy` (`launcher.ts`) did `const res = await fetch('/tools'); return res.ok;` and **never drained the body**. `/tools` is a large (~112KB) payload, so undici keeps the keep-alive socket **ref'd** until the tool-server's idle `keepAliveTimeout` (~5s) closes it. `ensureToolsServer` runs this health check on every invocation, and `run()`'s success path has no `process.exit(0)`, so the ref'd socket holds the event loop open. (Confirmed telemetry-independent — `DO_NOT_TRACK` made no difference.) The same undrained-body pattern existed in `link.ts` (`argent link`). ### Fix Drain the response body before returning in both health-check-style fetches: ```ts await res.body?.cancel().catch(() => {}); return res.ok; ``` (`fetchTools`/`callTool` were already fine — they `await res.json()`.) --- ## Testing **Empirical, end-to-end** (on a machine reproducing the wedged VVD): | Command | Before | After | | --- | --- | --- | | `argent run list-devices` | 6.15s | **0.91s** | | `argent run list-devices --help` | 6.14s | **0.16s** | | `argent tools` | 6.15s | **0.16s** | | handle probe after run | 2 sockets ref'd for ~6s | **none — immediate exit** | - Raw `POST /tools/list-devices` was ~0.7s throughout — confirming the ~5.4s was pure CLI teardown, not tool work. - **Process-group reap proven empirically:** the live `vega → bash → python3 → node` tree all shares the detached launcher's PGID; a group-SIGKILL left **0 survivors**. A real-subprocess test (unmocked `runVega` vs. a fake hanging `vega` on `PATH`) confirms it settles at its deadline **and** leaves **0 orphaned processes**. **Automated:** - `vega-cli-timeout.test.ts` (real-subprocess test) — `runVega` rejects on its deadline, **reaps the entire worker tree (0 orphans)** — the fake's hung worker is spawned into its **own** process group, so the test fails without the descendant sweep — and returns normally when the CLI responds. Also covers the boundary case: a **clean exit whose drain grace outlasts the deadline** resolves with its captured output rather than being rejected as a `timeout` (guards the `exit`-handler timer disarm above). - `vega-adb-connect-recovery.test.ts` — a *timed-out* `device list` does not trigger a second `device info` call (no stacking); a *fast, non-timeout* failure **still** recovers a running VVD. - `list-devices-deadline.test.ts` — `withDeadline` returns the branch value on the happy path and the fallback (with a logged note) when a branch exceeds the deadline. - `list-devices.test.ts` — added a `spawn` mock (vega moved off `execFile`). - `launcher-helpers.test.ts` — `isToolsServerHealthy` cancels (drains) its response body. - Suites green: **tool-server (1610), argent-tools-client (109), argent-cli (84)**. - eslint (`--max-warnings 0`), prettier, and `tsc` clean. ---	2026-07-01 11:02:33 +02:00