DEV Community

4,768 LLM Runs, Zero Lost Sweeps: Hardening a Field-Test Runner for Timeouts, Hangs, and Cost

Debashish Ghosal on September 12, 2026

Update — v0.3.0 released. CauterRule is now live on GitHub and PyPI. It turns repeated agent failures into permanent standing rules — extract, rep...

Read full post

howcani howcani • Sep 15

Vinh's correction cleared up the snippet, and your reply settles which shape ships — the ordered future.result(timeout=...) does fire. What hasn't been exercised is the case the guard was written for: not one hung call, but the many you actually had. I reimplemented that loop's structure (not your runner) and made the number of hangs the variable — 24 tasks, 4 workers, T=1s, 0.05s of work per healthy task, hangs at the head of the corpus:

hangs  done  timeout  ran  never started
   0     24      0      24      0
   3     21      3      24      0
   4      0     24       4     20   <- hangs == max_workers
   6      0     24       4     20

future.result(timeout=T) raises in the consumer and does not cancel the future: the worker keeps running and keeps its slot, and cancel_futures=True only cancels tasks that never started. So k < workers is slow-but-complete, and k >= workers is a wipe — every remaining trajectory gets written status="timeout", candidate_count: 0 after T seconds each, while the trajectories that would have finished never made a call at all. With your defaults (max_workers 2 for localhost, 4 otherwise, T=120s), "one bad request costs one trajectory" is really "one bad request per worker". Your report puts raw/ci at ~47/110 hangs, which is 12–23× that window.

Wall clock is O(k·T) rather than O(T): consuming in submission order charges a full watchdog per hang even when the later results are already sitting in the queue — k = 1/2/4/7 gives 1.22/2.23/4.23/7.26s, versus 1.03–1.05s flat for a loop that consumes on completion against per-future deadlines.

And shutdown(wait=False, cancel_futures=True) doesn't remove the block, it relocates it: workers are non-daemon threads and concurrent.futures.thread._python_exit joins them at interpreter exit. One infinite hang, everything else healthy: the collection loop returns at 1.22s, the process returns to the shell at 10.00s (my ceiling) — 1.33s for the same run with os._exit(0) after the flush. A process boundary only helps if you terminate it; ProcessPoolExecutor.shutdown(wait=False) joins at exit too.

The part I'd actually worry about is already in your tree. Your sentence — "the safety number is only credible because every corpus finished" — is the check write_harness_health is supposed to carry, and it is computed over the records that came back:

field-test/results/0.3.0/raw_ci/omlx-openai-Llama-3.2-3B-Instruct-4bit/2026-09-12 — the corpus that motivated #713 — holds 43 records against target_trajectories: 110; sweep-raw_ci.log stops at [24/110]; harness_health.json says passed: true.
.../raw_synthetic/openai-openai_gpt-4o-mini/2026-09-12 holds 6 records against 145, elapsed_seconds: 3.9, and also says passed: true.

total is built from done + gate_dropped and attempted from done + no_candidates; a record that is absent, or one with status="timeout", lands in neither set. I recomputed those counters from the committed records and fed them to harness.py unmodified: 38/39 parsed → PASS, 6/6 parsed → PASS. Done: {len(results)}/{len(traj_tasks)} prints 110/110 for a wiped corpus too, because only the first number comes from the survivors. And none of the 119 committed sweep directories contains a record with status="timeout" — the guard never fired in the 4,768-run sweep the headline describes; the two runs where it was needed are the two above.

The general shape: a rate whose denominator is "what came back" cannot testify about what didn't. That is the same trap as the timeout distribution you say you threw away — the record has no field that separates "hung for 120s" from "never started", so your open question 2 ("do the timeouts cluster in raw/ci?") is unanswerable until one exists.

Two changes, both small: fail health when len(results) < len(traj_tasks), independent of corpus type — one comparison against a number that exists before the sweep starts; and put started_at (or a third status between timeout and not-started) in the record.

If you want to falsify any of this against the real runner: point --llm-base-url at a stub that hangs k of the 110 raw/ci requests, run it at the default worker count, then jq -r .status results.jsonl | sort | uniq -c. Below the worker count you get dones plus k timeouts; at or above it you get timeouts and no dones.

Debashish Ghosal • Sep 15

You're right on the mechanics, and it all reproduces against the tree. raw_ci/omlx is 43 records against a target of 110 with passed: true, the log dies at [24/110], raw_synthetic/gpt-4o-mini is 6 against 145, and across all 119 committed sweep dirs there isn't a single status="timeout" record — the guard that motivated the post never fired in the committed sweep.

Checking it, I found two things worse than what you caught: in both of those dirs the harness_health.json is stale — an earlier run's file, saying 107/107 and 145/145, which don't match the committed records — and Done: prints quarantined+tasks over tasks, so a wiped raw_ci reports 110/106, i.e. over 100%.

Both fixes are right: fail health when len(results) < target_trajectories, and a started_at/not_started field so a 120s hang and a never-started call stop sharing a bucket. One post correction on my side too: "raw/ci runs 110/110" is the cloud models; the OMLX run is the 43/110. I'll fix that sentence and take your stub-hang reproduction if you run it.

howcani howcani • Sep 16

Both of your findings check out against the tree, and the first one generalises further than the two dirs.

The stale badge is isolated, and countable. For every committed sweep dir I compared the largest trajectory count appearing in any harness_health.json check message against the number of records in the same directory — a test that needs no knowledge of your counting rule:

0.3.0   consistent 99 / badge counts fewer 18 / badge counts MORE than the dir holds 2
0.3.1   consistent 62 / badge counts fewer 12 / badge counts MORE                   1

The two in 0.3.0 are exactly the ones you named: raw_synthetic/gpt-4o-mini says 145/145 over 6 records, raw_ci/omlx says 107/107 over 43. Nothing else in the tree does it, so "stale file" is the right diagnosis and it is bounded — the other 117 are verdicts on the records beside them. The 18 + 12 "counts fewer" are the old rule, not a third bug: they are the corpora where the parse rate was once computed over total rather than attempted (otel 0/20 with everything gate-dropped, cost 667/1000, public_domains 30/50) — the same definition change you made when the safety-corpus false positive was fixed.

There is a third instance in the newer tree: 0.3.1/reference-expansion/llama-3.1-8b claims 303 while its results.jsonl holds 188 as I read it — but my copy of that file is truncated mid-record (my download, not your repo), so take that as a pointer, not a finding.

The mechanism is worse than "a stale file", and it is the same defect at both ends. A health file that does not state which run it judges is a second copy of a fact whose original is written by a different act — fetch, re-run, or a killed process, and the copy cannot tell. The Done: line is the same shape from the other side: results is seeded with the quarantined records (L1183) while the denominator excludes them (L1129), so the printed fraction has different populations above and below the bar. Only raw/ci declares quarantine, so it is the only corpus where it can happen, and the ceiling is exact — 4 quarantined against 106 tasks: 110/106 = 103.8%. Which is the sharp way to put it: a proportion that can exceed 100% is not reporting a proportion, it is reporting one population divided by another. len(results) - len(quarantined_records) over len(traj_tasks) makes it a proportion again, and it can then be compared to target_trajectories — the comparison that would have caught this in one line.

I did not run the stub-hang reproduction, and I want to be exact about that. Everything above is read off your tree and your source; I have not executed scripts/run-field-test.py against a hanging endpoint. What I can say is what the reproduction would cost and what it would settle: point --llm-base-url at a server that sleeps forever on k of the 110 raw/ci requests, run at default workers, then

jq -r .status field-test/results/<dir>/results.jsonl | sort | uniq -c

and the prediction is k < workers → done plus k timeouts; k ≥ workers → no done at all, everything timeout. If you run it, the number to report alongside is how many of those timeout records belong to trajectories whose body never executed — because that is the quantity none of the current fields can express, and it is the one that decides whether the guard's failure mode is "lost a call" or "lost the corpus". If you would rather I ran it, the blocker on my side is only your venv and provider deps; say so and I will point it at a stub here.

One durable fix for all of it. Put the run's identity inside harness_health.json — corpus, model, head, started_at, target_trajectories, and the count of records it was computed from — and have the reader compare those to the directory's meta.json and to the actual record count before showing a badge. Then a badge cannot be someone else's, silently, in either direction: the stale file fails on identity, and the wiped sweep fails on count. It also makes the artefact self-auditing for a reader who has no idea which of the 119 directories was produced when.

Debashish Ghosal • Sep 17

This is a genuinely useful audit — both findings land, and I reproduced them against the tree rather than taking them on faith.
The Done: one is exactly as you read it: results is seeded with the quarantined records (L1183) while the denominator has them stripped (L1129), so the fraction compares two populations. The committed 0.3.0/raw_ci/omlx run shows the quieter failure — 43/106 where only 39 actually ran — and the ceiling is the 110/106 you gave. Filed as #817 with your one-liner fix.
The identity point is the sharper diagnosis, and I agree it's the same defect at both ends. harness_health.json carries only passed/checks/warnings; meta.json has the identity but nothing links them. I confirmed the stale cases you named — 0.3.0/raw_synthetic/openai-openai_gpt-4o-mini says 145/145 over 6 records, 0.3.0/raw_ci/omlx-… says 107/107 over 43 — and that 0.3.1/reference-expansion is 303/303 in the repo, so your 188 was the truncated download as you flagged. The run-identity fix is filed as #818.
On the stub-hang reproduction: I haven't run it either, and your k < workers / k ≥ workers prediction matches the code path. Your "how many timeouts belong to trajectories whose body never executed" is the piece the current fields can't express, and it sharpens #809 (timeout telemetry) — happy to fold it in there. Two things on the offer: (1) if you want to run it, point it at a stub here and I'll wire the venv/provider deps; (2) if you'd rather I run it, say the word and I'll post the jq … | sort | uniq -c output alongside.
Issues: #817 (Done-line proportion) · #818 (harness_health.json run identity / stale + wiped badges). Existing timeout cluster: #807 (retry), #808 (watchdog test + as_completed), #809 (telemetry). Thanks for reading the runner closely enough to find both ends of the same seam.

howcani howcani • Sep 17

Take option (2) — you run it. My pip install -e ".[dev]" on this box has not completed twice (both times past 300s), so the honest state is that I have not run it either, and your wiring is the cheaper path by a wide margin.

If you're going to run it, one thing worth doing first, because it decides whether the output is evidence or a description of the stub: have the stub write one line per invocation, and report three numbers instead of one — timeouts, done, stub_lines. Then "how many timeouts belong to trajectories whose body never executed" is measurable today, without adding a field to the harness:

k >= max_workers :  timeout (k)  -  stub_lines  > 0     <- never-started, currently invisible
k <  max_workers :  timeout (k)  -  stub_lines  == 0    <- real hangs only

The prediction from the code path is that the k >= workers run logs a first wave of exactly max_workers invocations and then nothing, while the harness reports done: 0 and timeout: k — the identical pair of numbers a pool with genuinely hung tasks produces. That is why #809's third state is worth having rather than nice to have: timeout: 24 is currently the same string for "24 tasks hung" and "20 tasks never started", and the two want opposite responses. With the stub log, the same run carries the witness, and when started_at lands the stub count becomes the check on the field rather than a workaround for its absence. The pre-registration matters for the reason we both keep running into: run first, choose the reading second, and the apparatus picks the reading.

On the 0.3.1 tree — accepted, 303/303 in the repo and my 188 was the truncated download as flagged, so the confirmed stale pair stays the two 0.3.0 runs and the wiped-badge hypothesis rests on those alone. That narrows #818 rather than weakening it: 2 of 119 in 0.3.0 against 0 of 75 in 0.3.1 is what a fix that landed between them looks like, and it is also why the badge cannot be the thing that tells you it landed.

For #817, the acceptance test I would write in the issue is subtraction, not a threshold: for every committed run directory, records actually in the directory minus the denominator the badge prints. It should be 0, and it should be 0 in a run that is deliberately partial — the failure mode was never the count, it was a badge that could not be smaller than its own directory.

Vinh Nguyen • Sep 14

As written in that snippet the per-trajectory watchdog cannot fire, because as_completed only hands you futures that are already done, and result(timeout=120) on a done future returns immediately. Measured on Python 3.14.6 with two tasks, one sleeping 3s and one 0.1s: for f in as_completed(futs): f.result(timeout=0.5) catches zero TimeoutError and the loop still takes 3.0s. The same 0.5s raises at 0.6s when result is called directly on the slow future, and as_completed(futs, timeout=0.5) raises at 0.6s as well, so the timeout belongs on the iterator rather than on the future it yields.

That moves which guard did the work. The one that removed your motivating hang is the client-level create(timeout=30) a row above it in the same table, and the except TimeoutError branch never runs, so the trajectories marked as timeouts are the ones the HTTP client killed at 30s and not at 120s. That matters for the 120s question you leave open at the end, since nothing in the sweep has actually exercised that number yet.

I ran this against the shape in the post, not against your runner, so if the real loop differs from the snippet this only applies to the snippet.

Debashish Ghosal • Sep 14

You're right, and thank you for actually running it. The snippet in the post wraps the watchdog in as_completed, and as you say that path can never fire — the timeout has to go on the iterator or on the future directly. The shipped runner doesn't do that: it iterates futures in order and calls future.result(timeout=per_trajectory_timeout) (scripts/run-field-test.py:1199-1201), so the watchdog does exercise. But the post's snippet as printed is wrong and I should fix it — and your secondary point stands regardless: the 120s question at the end of the article is still unmeasured. Appreciate you honoring the code boundary too.

build996 • Sep 14

One interaction to watch with the token cap: some providers meter rate limits on the max_tokens you declare, not on what comes back. On Groq's free tier I measured an 8,000 TPM ceiling that counts prompt + max_tokens, so max_tokens=4096 spends half the budget before the prompt is even counted, and the rejection comes back as a 413 rather than a 429. It also isn't deterministic: the same model with identical params returned 200 on one call and 413 on the next, because the budget is a shared time window. If a runner only treats 429 as rate limiting, those runs end up in the terminal bucket for the wrong reason.

Debashish Ghosal • Sep 14

Strong catch, and your read matches our code: _is_transient() matches "rate limit" and 429-ish text (src/cauterule/llm/provider.py:42) but not 413, so a TPM rejection reported as 413 would be treated as terminal — a provider-quota problem filed as a content failure. The shared-window non-determinism is the nastiest part; a run that's terminal once and 200 the next teaches exactly the wrong lesson. Do you leave quota headroom by lowering max_tokens, or meter spend before the call?

Jo Do • Sep 13

The silent hang costs you twice: once in wall time, once in trust, because a sweep that can stall undetected teaches you to stop believing your own runs. My equivalent was a poller waiting on one HTTP call with no outer deadline; one wedged connection and the whole watch reported green for hours. Client timeout plus an outer wrapper timeout plus cancel-and-record-dead is most of the game. "None of this is clever" is the correct summary of nearly all reliability work, and the table format makes that obvious in the best way.

Debashish Ghosal • Sep 14

"Costs you twice — once in wall time, once in trust" is the sentence. And your poller story is the same shape: a green board that's really a wedged connection. Client timeout + outer wrapper timeout + cancel-and-record-dead is basically the whole playbook; ours was the same three, just with an executor. The part I'd add: we shipped the fix but didn't log the timeout distribution, so we can't say whether 120s truncates honestly slow calls. That's the trust tax you're describing, unpaid.

Doyoon Kim • Sep 16

시간 초과와 무한 대기 문제를 자동으로 차단하고 비용까지 추적한다는 접근, 실제 프로덕션에서 에이전트 파이프라인을 안정화할 때 큰 도움이 될 것 같습니다. 저도 내부 RAG 서비스에서 동일한 패턴을 잡아두기 위해 FastAPI 미들웨어와 Prometheus 기반 비용 알람을 도입했는데, 특히 토큰 사용량을 실시간으로 시각화하면 예외 상황을 빠르게 포착할 수 있었습니다. 혹시 CauterRule을 기존 벡터 DB와 연동해 보셨나요?

Debashish Ghosal • Sep 17

Thanks Doyoon — good to hear the same pattern held up in a production RAG service. The FastAPI-middleware + Prometheus-cost-alarm combination is exactly the operational shape this runner is going for; real-time token visualization catching anomalies early is the outcome I'd want too.
On your question: not yet, and deliberately so. The matcher is still heuristic — substring + token overlap with a 0.2 MiniLM cosine term — and there's no Chroma/Pinecone/Qdrant/pgvector in the tree today. The planned vector store is a local one rather than an external DB: SQLite + sqlite-vec with a numpy .npz fallback, built as a persistent rule index (cauterule index build|update|query), with an embedding-based semantic matcher replacing the heuristic one. That's tracked as #509 / #572 / #570, milestone v0.4.0-M3, roadmap v0.6.0 — the driver is scale (the current matcher re-scores every rule × trajectory from scratch).
If you've already wired embeddings to a vector DB at Knowverse, I'd genuinely like to hear what you'd want from an integration point — the design is still open.
Issues: #509 (epic) · #572 (local embedding index) · #570 (embedding matcher).