Issues / #1527
#1527 serve: the engine READY read times out and the engine is killed, but the pending request is still held (0.1.40.3)
open · @justxiami · 2 comentários · No GitHub
Server & APIMulti-GPUNVIDIA / CUDAModels & quantsLinux
Descrição
## Summary
The read timeouts that 0.1.40.2 took from #1317 do bound the **engine `READY` read** (the hung engine gets killed), but the request turn is **not released**: the client gets no response and the server prints no reason. Tested on a pristine `v0.1.40.3` checkout, so this is not a merge artifact of my tree.
The same server does fail cleanly in the neighbouring case — engine already `READY`, then silent during a request: HTTP 503 with a clear message after `engine_silence_s`. So the gap is specific to "the engine is alive but never reports READY".
This is a serve-only finding: no GPU, no model, no engine binary is needed to reproduce.
## What 0.1.40.2 fixed, and what is left
From #1317 (still open), and @Niko1221's reply: *"0.1.40.2 takes the read timeouts: the engine's READY read now gives up after 900 s, and the image encoder's READY and ENC reads after 300 s each … A process that says nothing for that long is killed, the request fails with a clear message and the next one starts it again."*
Measured on 0.1.40.3 (both claims tested, same machine, same fake processes, `STRATA_ENGINE_READY_S=8`, `engine_silence_s=60` in the config):
| Scenario | Engine process | The request turn |
|---|---|---|
| Engine never reports `READY` (load path) | killed at ~8 s — the timeout fires | **no HTTP response at all**: 130.00 s on 0.1.40.3, 320.00 s on our build; `curl` reports `code=000`; the server prints nothing containing `did not report READY` (0 hits) |
| Vision encoder starts and says nothing | killed at 8 s | fails with `RuntimeError: the vision encoder did not start: it said nothing for 8 s` (`serve/server.py:1716`) |
| Engine `READY`, then silent mid-request | ended by the watchdog | **HTTP 503 at 61.14 s**: `the engine said nothing for 61 s during the request; the server ended the engine; the next request restarts it` |
So "killed" is delivered, "the request fails with a clear message" is not delivered in the first row.
## Reproduction (no GPU, no model, no engine build)
1. A fake engine that starts and never says `READY`:
```bash
#!/bin/bash
# fake_engine_silent.sh
trap 'exit 0' TERM INT
sleep 3600
```
2. A config that points `exe` at it (any existing serve config works; `vision` removed, `log` and `cwd` pointed at a scratch dir).
3. Start serve with `--lazy` so the port is bound before any loading, then send one request:
```bash
STRATA_ENGINE_READY_S=8 python serve/server.py --engine strata \
--config /tmp/cfg.json --port 8099 --host 127.0.0.1 --tokenizer <a real tokenizer dir> --lazy
curl -s -m 130 -o out.json -w "%{http_code} %{time_total}s\n" \
http://127.0.0.1:8099/v1/chat/completions -H 'Content-Type: application/json' \
-d '{"model":"qwen3.8-flash-next","temperature":0,"max_tokens":8,"messages":[{"role":"user","content":"hi"}]}'
```
Expected (the patch's promise): the request ends with a clear failure. Actual: the request never returns (curl gives `000 130.00 s`), the server's stdout stops at
```
[strata] loading the model again (it was unloaded) ...
[strata] starting the engine: reading the model's weights ...
```
and nothing more. The fake engine is gone by the first status check after the timeout, so the `READY` read did give up.
The control arm (the second row above) is the same script with this fake engine instead:
```bash
#!/bin/bash
# fake_engine_ready.sh — says READY, then never answers again
printf 'READY 32768 stop\n'
trap 'exit 0' TERM INT
while IFS= read -r _; do :; done
```
That one returns 503 with the reason in 61.14 s.
## Why the existing watchdogs do not cover it
- `engine_silence_s` (#481) is armed after the request has been handed to the engine; here the blocking read never returns before the request is armed. #1317's own report says this.
- The engine-side #29 watchdog only counts while a request is running; the engine never got one.
- #1317's patch also carried a stall watchdog that watches both log silence and the engine's CPU time (`ENGINE_STALL_S`, `_cpu_flat_for`, `_cpu_seconds`, `_frozen(`, `gen_active`, `last_line_at`). A pristine `v0.1.40.3` `serve/server.py` has **0 occurrences of all six**, so that half of the patch was not taken. (Not the cause of the row-1 gap — the `READY` timeout does fire — but it is the reason nothing else notices a load that never completes.)
## What I did not determine
I did not localise which wait keeps the request thread. The `READY` timeout raises `RuntimeError`, `restart()` catches it and retries (`RESTART_RETRY_S`), re-raising only on the last try — yet no retry line ("the engine did not start (try i of N)") is printed in this scenario, and the client socket stays open with no bytes. Also untested: whether the same holds without `--lazy` (in that case the port is never bound at all, so a client cannot even connect — during a cold-start hang the server offers nothing, which is arguably a separate symptom).
## What I would want
Once the `READY` read times out and the engine has been killed, the load attempt should fail the pending request the same way the #481 path does — 503 plus the reason the server already computed — and let the next request start a new engine, instead of holding that turn open.
## Environment
- Pristine `v0.1.40.3` tree (`serve/server.py` md5 `c7a94436b69f`) and, as a second arm, a 0.1.40.1-based serve carrying the three #1317 commits merged by hand (md5 `9b690b1249a7`). Same result in both.
- Linux (Ubuntu), Python 3.12, 4×V100 (sm_70) host, `--layer-split 12,24,36` in the config used for the arms (irrelevant: the engine is a stub).
- Both arms run side by side on ports 8098/8099 with the same config file and the same fake processes; the only difference between the arms is which `serve/server.py` is started.
No site
Links install, modelos, releases.