#1317 serve: an untimed read of the engine/vision pipe can hold the request turn forever (intermittent hang; the #481 lost-step class)

本文

## Summary

On **v0.1.40.1** (engine 0.1.40), running **Qwen3.8-Flash-Next IQ3_XXS**, the server intermittently hangs after it has been serving requests for a while: the current request stops progressing (the panel shows *"waiting for token generation"*) and every later request stays *"queued"* forever. The **engine is not stuck** -- it is idle in its command loop; the server simply never finishes the request, so it never releases the single request turn.

## Environment

- Strata source 0.1.40.1 (engine 0.1.40), Windows, 2x RTX (3080 Laptop + 3070 Laptop, 16 GiB each), Xeon E5-2680 v4.
- Model: Qwen3.8-Flash-Next IQ3_XXS, `--vision`, `--kv int8`, `--spec 4`, `--prefill auto:32768`, `--max-context 262144`, `--pipeline-windows 2`, no `parallel` (1 request at a time).
- Not deterministic: it appears only after the server has been running and serving requests for a while.

## Observed

- The stuck request sits at phase `reading` with `generated: 0`, while the engine log already shows the request finished (e.g. `prompt 56959 tokens ... 490 generated ... drafts accepted 366 of 369`). The server never reads the end of the request.
- `strata.exe` CPU time is frozen (e.g. pinned at `308.4375 s` across repeated samples) -- it is **idle waiting for a command**, not spinning. Because of that the engine-side #29 watchdog (which only counts while a request is running) never fires.
- `/status` shows `busy:false, queued:N` while the UI still reports a running/queued request.

## Root cause

This is the **#481 "lost step"** class, with a concrete trigger: the server has **blocking reads of the engine/vision pipes that have no timeout**. If one of them never returns (the vision encoder's `READY`/`ENC` read, or the engine's `READY` read), the request turn is held forever. By then the engine has already finished (or never saw the request), so no engine-side watchdog can fire and the request never ends; later requests queue behind it.

Upstream's `engine_silence_s` (v0.1.37, #481) covers a *running* request that goes silent, but it is armed only after the request has been sent to the engine -- it does not cover a blocking read that never returns before the request is armed.

## Fix (patch below)

Time out every blocking read and add a watchdog that can end a genuinely silent engine:

- `VISION_READY_S=300`, `VISION_ENCODE_S=300` -- the vision-encoder reads go through `Vision._readline(timeout, what)` (a pump thread + queue); on timeout the encoder is killed and the request fails cleanly instead of hanging.
- `ENGINE_READY_S=900` -- the engine `READY` read goes through a `_ready_pump` thread + `queue.get(timeout=...)`.
- `ENGINE_STALL_S` (default 90 s, override with `STRATA_ENGINE_STALL_S`; 0 disables) -- while a request is active, if the engine prints nothing **and** its CPU time has not advanced, the engine is ended so the next request restarts it.
- `FIFO_WARN_S=600` -- a one-shot diagnostic line if a request holds the turn that long.
- A small `TurnLock` wrapper that records how long the turn has been held.

All of these are server-side only; no engine rebuild is needed.

## Evidence

- Reproduced live: `strata.exe` CPU frozen at `308.4375 s`, `/status` `state="reading"`, `elapsed_s=462.8`, `in_flight=2`, while the engine log showed the request already completed.
- After the patch: `serve/test_server.py` (204 tests) plus the companion tests pass; a 9-request stress run (image/vision + a 35k-token prompt + back-to-back + concurrent) and a ~10 min soak (three.js generation, 6 rounds) all completed with no hang.

## Relation to existing issues

- **#481** (open) -- same lost-step class (this report adds a concrete, reproducible trigger: an untimed blocking read holding the request turn).
- **#1012** (closed, fixed in 0.1.40.1) -- the restart-waiters variant.

## Patch

`strata-hang-fix.patch` (15 hunks, +230 / -16) -- apply to `serve/server.py`.

<!--PATCH-->


```diff
diff --git a/serve/server.py b/serve/server.py
index d6b1fc3..935f191 100644
--- a/serve/server.py
+++ b/serve/server.py
@@ -211,6 +211,27 @@ SESSION_WAIT_MAX_S = 3600
 PP_CHUNK_MAX = 32768
 PP_FLOOR_TOK_S = 50.0
 PP_SLACK = 3.0
+# The image encoder's own backstop: a read from it with no timeout held the request FIFO for good when it
+# stopped answering - the engine then sat idle in its command loop, no watchdog could fire, and the request
+# never ended (the "lost step" class of #481).  Generous on purpose: a cold model load or a slow CPU encode
+# is not a hang, and the encoder is ended (the next request starts it again) only when it says nothing at all.
+VISION_READY_S = 300.0
+VISION_ENCODE_S = 300.0
+# The engine's own READY read has no timeout either (an engine that starts but never reports READY, or a
+# start that hangs in the loader, held the request FIFO for good).  Same treatment, longer: loading 47 GB of
+# experts on a slow disk takes minutes.
+ENGINE_READY_S = 900.0
+# A request may hold the FIFO for as long as its work takes, but a holder that stays silent this long is
+# reported once to the server window - a diagnostic, never a kill (a vision read or a load that hangs is
+# exactly what the two watchdogs above cannot see).
+FIFO_WARN_S = 600.0
+# The engine's own #29 watchdog covers a request whose heartbeat stops while it is busy, but a frozen host
+# thread (a deadlock inside a CUDA call, a driver stall) never reaches it: the engine burns CPU once, then its
+# CPU time stops and it sits there for good while the server waits.  Seen on 2026-10-07 - the engine's CPU time
+# stopped at 308.4 s and never moved again, GPU 0 %, /health still said loaded, and neither watchdog fired.
+# So watch the engine's own CPU time while a request is outstanding: it must advance, or the engine is frozen
+# and is ended (the next request starts it again).  STRATA_ENGINE_STALL_S sets it (0: off).
+ENGINE_STALL_S = float(os.environ.get("STRATA_ENGINE_STALL_S") or 90.0)
 
 
 # ------------------------------------------------------------------------------------------------ engines
@@ -608,7 +629,23 @@ class StrataEngine:
                           stdout=subprocess.PIPE, stderr=self.log, text=True, encoding="utf-8", bufsize=1, env=env)
         contain(self.proc)                               # ends with the server, however it ends (Windows)
         self.max_context = 0
-        for line in self.proc.stdout:
+        ready_q: queue.Queue = queue.Queue()
+        threading.Thread(target=self._ready_pump, args=(self.proc, ready_q), daemon=True).start()
+        deadline = time.monotonic() + ENGINE_READY_S
+        timed_out = False
+        while True:
+            left = deadline - time.monotonic()
+            if left <= 0:
+                timed_out = True
+                loading.set()
+                break
+            try:
+                line = ready_q.get(timeout=left)
+            except queue.Empty:
+                continue
+            if line is None:
+                loading.set()
+                break
             if line.startswith("INFO "):
                 for kv in line.split()[1:]:
                     k, _, v = kv.partition("=")
@@ -618,9 +655,14 @@ class StrataEngine:
                 self.max_context = int(f[1])
                 self.can_stop = "stop" in f[2:]
                 break
-        loading.set()
+        loading.set()                                   # READY (or a dead engine): the narrator stops (#481 patch regression)
         if self.max_context <= 0:
-            try:                                        # its pipes and our handle on its log (the log stays)
+            if self.proc.poll() is None:
+                try:
+                    self.proc.terminate()
+                except OSError:
+                    pass
+            try:
                 self.proc.wait(timeout=5)
                 self.proc.stdin.close()
                 self.proc.stdout.close()
@@ -628,7 +670,9 @@ class StrataEngine:
                     self.log.close()
             except (OSError, subprocess.TimeoutExpired):
                 pass
-            raise RuntimeError("the engine exited before it was ready" + (f" (see {log})" if log else "") +
+            why = (f"the engine did not report READY within {ENGINE_READY_S:.0f} s" if timed_out else
+                   "the engine exited before it was ready")
+            raise RuntimeError(why + (f" (see {log})" if log else "") +
                                start_failure_hint(log, log_start) + start_log_tail(log, log_start))
         self.known_ctx = self.max_context   # survives a failed restart: requests keep their limit and restart it
         # (from PR #41, midhatn) a locally built engine can sit next to another release's BUILD.json: engines that
@@ -668,6 +712,9 @@ class StrataEngine:
             self.ctl_epoch = 0                          # how often the control lines were taken
             self.ctl = threading.Lock()                 # one admission or solo request on the control lines at a time
         self.gen = self.__dict__.get("gen", 0) + 1      # which engine process this is (a request notes its own)
+        self.gen_active = False                         # a request is being generated (the stall watchdog reads it)
+        self.last_line_at = time.monotonic()            # when the engine last printed a line (the stall watchdog)
+        self._cpu_last, self._cpu_moved_at = None, 0.0  # its CPU time, and when it last moved (the stall watchdog)
         self._yielded = None                            # (slot, tokens read): the last request on them gave way
         self.wlock = threading.Lock()                   # stdin writes from several request threads
         self.pump = threading.Thread(target=self._pump, daemon=True)
@@ -697,6 +744,8 @@ class StrataEngine:
                 except (IndexError, ValueError):
                     pass
             lines.put(line)
+            if self.proc is proc:
+                self.last_line_at = time.monotonic()     # the stall watchdog: the engine is still saying something
         if self.proc is proc:                           # a killed engine's pump must not mark its successor dead
             self.ended = True                           # its output closed: it is gone, even before the OS says so
             if line and line.startswith("ERR"):         # #997 #890: why it exited, though no request may read it
@@ -705,6 +754,68 @@ class StrataEngine:
         for q in slot_q:
             q.put(None)
 
+    def _cpu_seconds(self) -> float | None:
+        """The engine process's own CPU time (all threads), or None when psutil is not there.  A frozen engine's
+        CPU time stops advancing, which is the one liveness signal neither watchdog uses."""
+        proc = self.proc
+        if proc is None or proc.poll() is not None:
+            return None
+        try:
+            import psutil
+        except Exception:  # noqa: BLE001 - psutil is optional
+            return None
+        try:
+            t = psutil.Process(proc.pid).cpu_times()
+            return float(t.user + t.system)
+        except Exception:  # noqa: BLE001 - the process went away
+            return None
+
+    def _cpu_moved(self, cpu: float | None) -> None:
+        """Remember the engine's CPU time for the stall watchdog: when it last moved, and from what."""
+        if cpu is None:
+            self._cpu_last, self._cpu_moved_at = None, 0.0
+            return
+        if self._cpu_last is None or cpu > self._cpu_last + 1e-9:
+            self._cpu_last, self._cpu_moved_at = cpu, time.monotonic()
+
+    def _cpu_flat_for(self, cpu: float | None) -> float:
+        """How long the engine's CPU time has stood still (0 when it just moved, or was never seen)."""
+        if cpu is None or self._cpu_last is None or not self._cpu_moved_at:
+            return 0.0
+        return time.monotonic() - self._cpu_moved_at
+
+    def _frozen(self, what: str) -> EngineSilent:
+        """End an engine whose CPU time stopped advanc