Skip to content

Commit cf426cd

Browse files
committed
fix(daemon): a 503 is an answer, not a wedge — stop restarting a healthy
service under load GH #1419 Issue 3b (Steve postmortem): the supervisor cycled nexus-service after 3 consecutive failed health checks caused purely by CPU-bound local embedding, not by any failure — severing a client mid-batch. MECHANISM, verified on both sides of the wire. GET /health is implemented engine-side as dataSource.getConnection() + SELECT 1 (HealthHandler.java), so it takes a HikariCP pool connection. The supervisor probed it with a 2s timeout and exited for an OS restart after 3 consecutive failures at 1s — a 3-second grace window. Under indexing load the pool is contended, /health blocks past 2s, the counter fills, and the service is restarted. The probe that decides whether to KILL the service competes for the exact resource saturation exhausts, so the loop is self-amplifying: load -> restart -> in-flight clients severed -> retries -> more load. THE DEEPER DEFECT: _service_healthy returned a bare bool, collapsing "answered 503" and "did not answer at all" into one False. Those are opposite pieces of evidence. A 503 proves the process is ALIVE and talking — its dependency is unhappy — and restarting it cannot fix a down database while it certainly does sever clients. Only silence is consistent with a wedge. So the probe is now tri-state (HealthProbe OK / UNREADY / UNKNOWN) and ONLY UNKNOWN advances the restart counter. UNREADY resets it, declines to stamp the lease (consumers should not be routed to a service saying it cannot serve), and logs. _service_healthy survives as a boolean for the STARTUP readiness gate, where UNREADY and UNKNOWN really are equivalent. BOUNDED, AND HONESTLY SO. Widening the probe budget hits an invariant: the probe blocks the heartbeat thread, so a tick costs _HEALTH_TIMEOUT + heartbeat interval and the lease TTL must be >= 3x that (test_ttl_exceeds_worst_case_heartbeat_tick). With TTL 15s that caps the probe at exactly 4.0s. A first attempt at 20s tripped that test — the supervisor would have lost its OWN lease mid-probe, trading a spurious restart for a vanished endpoint. 4.0s x 4 beats = ~16s of total silence before restart, up from ~6s, at the invariant boundary with no margin left. That mitigates the saturation case rather than closing it: a pool whose own connectionTimeout is 30s can still outlast a 4s probe. Closing it needs a dependency-free engine liveness endpoint and/or the probe off the heartbeat thread — filed as nexus-hubc0, engine half batched into v0.1.55. The 503-vs-timeout distinction shipped here is what actually protects the DB-unhappy case, and it stands on its own. 9 new tests, each RED first, driving a REAL loopback server on port 0 whose status is switchable rather than stubbing the probe — a classifier that never classifies would otherwise pass. Two existing heartbeat tests re-pointed at the tri-state seam; the eight startup-gate stubs keep the boolean by design. Bead: nexus-7f7gb Follow-up: nexus-hubc0
1 parent 6907e23 commit cf426cd

3 files changed

Lines changed: 332 additions & 16 deletions

File tree

src/nexus/daemon/storage_service_daemon.py

Lines changed: 99 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -65,6 +65,7 @@
6565
import subprocess
6666
import threading
6767
import time
68+
from enum import Enum
6869
from pathlib import Path
6970
from typing import Any, Callable, Optional
7071

@@ -103,6 +104,25 @@
103104
_LIBC = _pdeathsig.LIBC
104105
_set_pdeathsig_preexec = _pdeathsig.set_pdeathsig_preexec
105106

107+
class HealthProbe(Enum):
108+
"""Outcome of a ``GET /health`` probe (nexus-7f7gb).
109+
110+
Three states, because two were not enough to make a restart decision:
111+
112+
- ``OK`` — 200. Serving.
113+
- ``UNREADY`` — answered with a non-200 status. The process is ALIVE and
114+
talking; its dependency is unhappy. Restarting cannot fix that and does
115+
sever in-flight clients, so this never counts toward a restart.
116+
- ``UNKNOWN`` — no answer at all (timeout, refused, unset port). The only
117+
evidence consistent with a wedged process, and therefore the only state
118+
that advances the restart counter.
119+
"""
120+
121+
OK = "ok"
122+
UNREADY = "unready"
123+
UNKNOWN = "unknown"
124+
125+
106126
#: Path suffix of the spawn lock file inside config_dir.
107127
_SPAWN_LOCK_FILE: str = "storage_service_spawn.lock"
108128

@@ -115,8 +135,26 @@
115135
#: After SIGTERM, wait this long before escalating to SIGKILL.
116136
_GRACEFUL_STOP_TIMEOUT: float = 5.0
117137

118-
#: Short HTTP timeout for /health probes.
119-
_HEALTH_TIMEOUT: float = 2.0
138+
#: HTTP timeout for /health probes.
139+
#:
140+
#: nexus-7f7gb (GH #1419 Issue 3b): was 2.0s, BELOW the contention window it
141+
#: had to survive. ``GET /health`` is implemented engine-side as
142+
#: ``dataSource.getConnection()`` + ``SELECT 1`` (HealthHandler.java), so it
143+
#: takes a HikariCP pool connection — and the pool's own connectionTimeout is
144+
#: 30s. Under CPU-bound indexing the pool is contended, /health blocks well
145+
#: past 2s, and a probe budget that small made "the pool is busy"
146+
#: indistinguishable from "the process is wedged". The probe that decides
147+
#: whether to KILL the service must not be tighter than the resource it
148+
#: contends for.
149+
#:
150+
#: CEILING (test_ttl_exceeds_worst_case_heartbeat_tick): the probe BLOCKS the
151+
#: heartbeat thread, so the tick can take _HEALTH_TIMEOUT + heartbeat interval
152+
#: and the lease TTL must be >= 3x that. With TTL 15s that caps this at 4.0s.
153+
#: Raising it further requires either a larger TTL (which widens the
154+
#: post-restart stale-endpoint window, nexus-om64x) or moving the probe OFF
155+
#: the heartbeat thread — see the follow-up bead. 4.0s is the largest value
156+
#: the current invariant allows, not the value the problem wants.
157+
_HEALTH_TIMEOUT: float = 4.0
120158

121159
#: The storage-service lease TTL is a SUBSTRATE parameter — it lives in the shared
122160
#: primitive (``service_registry.TIER_TTLS["storage_service"]``, resolved via
@@ -133,11 +171,18 @@
133171
#: stuck-but-alive states (connection-pool exhaustion, GC pause, internal
134172
#: deadlock) that are the most common partial-failure mode — and which the OS
135173
#: watchdog (RDR-175) cannot catch on its own, since it only sees process
136-
#: death. 3 beats at 1s interval = a 3s grace window before exit — large
137-
#: enough to absorb transient GC pauses, small enough to recover quickly from
138-
#: real deadlocks. RDR-175 retired the in-process respawn mechanism; this
174+
#: death.
175+
#:
176+
#: nexus-7f7gb: was 3, which with the old 2s probe gave a ~3s grace window —
177+
#: an ordinary indexing burst crossed it and cycled the service mid-batch,
178+
#: severing in-flight clients (which then retried, adding load: the loop was
179+
#: self-amplifying). Only UNKNOWN beats (no answer AT ALL) advance this
180+
#: counter now; a 503 means the service ANSWERED and is not a wedge. 4 beats
181+
#: x ~5s tick = ~20s of total silence before the supervisor exits for
182+
#: an OS restart — long enough that saturation cannot masquerade as death,
183+
#: short enough that a real deadlock is still caught. RDR-175 retired the in-process respawn mechanism; this
139184
#: DETECTION is retained but its action is now exit-for-OS-restart, not respawn.
140-
_MAX_UNHEALTHY_HEARTBEATS: int = 3
185+
_MAX_UNHEALTHY_HEARTBEATS: int = 4
141186

142187

143188
# ── Errors ─────────────────────────────────────────────────────────────────────
@@ -644,19 +689,43 @@ def _spawn_service(self) -> tuple[subprocess.Popen[bytes], int]:
644689
)
645690
return proc, port
646691

647-
def _service_healthy(self, port: int | None = None) -> bool:
648-
"""Return True iff the service /health endpoint returns HTTP 200."""
692+
def _probe_service_health(self, port: int | None = None) -> "HealthProbe":
693+
"""Classify ``GET /health`` into :class:`HealthProbe`.
694+
695+
nexus-7f7gb: the predecessor returned a bare bool, collapsing
696+
"answered 503" and "did not answer at all" into one False. Those are
697+
OPPOSITE pieces of evidence about liveness — a 503 proves the process
698+
is alive and answering, while silence is the only thing suggesting a
699+
wedge — and treating them alike is what let an indexing burst kill a
700+
healthy service.
701+
"""
649702
_port = port if port is not None else self._service_port
650703
if _port <= 0:
651-
return False
704+
return HealthProbe.UNKNOWN
652705
url = f"http://{_SERVICE_HOST}:{_port}/health"
653706
try:
707+
import urllib.error # noqa: PLC0415 — deferred import — branch-local
654708
import urllib.request # noqa: PLC0415 — deferred import — platform/heavy dep loaded only on the path that needs it
655709
req = urllib.request.Request(url, method="GET")
656710
with urllib.request.urlopen(req, timeout=_HEALTH_TIMEOUT) as resp:
657-
return resp.status == 200
658-
except Exception: # noqa: BLE001 — best-effort reachability probe; returns False on any error
659-
return False
711+
return HealthProbe.OK if resp.status == 200 else HealthProbe.UNREADY
712+
except urllib.error.HTTPError:
713+
# An HTTP status IS an answer: the process is up and serving, its
714+
# dependency is not. Never a restart reason — restarting cannot
715+
# fix a down database and does sever in-flight clients.
716+
return HealthProbe.UNREADY
717+
except Exception: # noqa: BLE001 — no answer: timeout, refused, anything
718+
return HealthProbe.UNKNOWN
719+
720+
def _service_healthy(self, port: int | None = None) -> bool:
721+
"""Back-compat boolean: True iff /health answered 200.
722+
723+
Retained for the STARTUP readiness gate, which genuinely wants "is it
724+
serving yet" and for which UNREADY and UNKNOWN are equivalent. The
725+
HEARTBEAT path must use :meth:`_probe_service_health` — there, the
726+
distinction is the whole point.
727+
"""
728+
return self._probe_service_health(port) is HealthProbe.OK
660729

661730
def _pg_reachable(self) -> bool:
662731
"""Return True iff the Postgres port accepts TCP."""
@@ -947,13 +1016,30 @@ def heartbeat_once(self) -> tuple[bool, bool]:
9471016
return False, False # process exited; signal the run loop to exit
9481017

9491018
service_alive = _pid_is_alive(self._proc.pid)
950-
service_ok = self._service_healthy()
1019+
probe = self._probe_service_health()
1020+
# nexus-7f7gb: UNREADY (answered non-200) is NOT a wedge — only total
1021+
# silence counts toward the restart threshold.
1022+
service_ok = probe is HealthProbe.OK
9511023
pg_ok = self._pg_reachable()
9521024

9531025
if not service_alive:
9541026
self._consecutive_unhealthy_heartbeats = 0
9551027
return False, pg_ok
9561028

1029+
if probe is HealthProbe.UNREADY:
1030+
# Answered, therefore alive. Reset the wedge counter, and do NOT
1031+
# stamp the lease — consumers should not be routed to a service
1032+
# telling us it cannot serve. It simply is not a restart reason.
1033+
self._consecutive_unhealthy_heartbeats = 0
1034+
_log.warning(
1035+
"storage_service_unready",
1036+
pg_ok=pg_ok,
1037+
port=self._service_port,
1038+
msg="/health answered non-200 — alive, dependency unhappy; "
1039+
"not counting toward restart",
1040+
)
1041+
return True, pg_ok
1042+
9571043
if not service_ok:
9581044
self._consecutive_unhealthy_heartbeats += 1
9591045
_log.warning(
Lines changed: 219 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,219 @@
1+
# SPDX-License-Identifier: AGPL-3.0-or-later
2+
"""nexus-7f7gb (GH #1419 Issue 3b): a 503 must not restart the service.
3+
4+
Steve Harris watched the supervisor cycle ``nexus-service`` after 3 consecutive
5+
failed health checks caused purely by CPU-bound local-embedding load, not by
6+
any failure. A client mid-batch loses its connection when that happens.
7+
8+
MECHANISM (verified on both sides of the wire):
9+
10+
* ``HealthHandler.java`` implements ``GET /health`` as
11+
``dataSource.getConnection()`` + ``SELECT 1`` — it takes a HikariCP pool
12+
connection.
13+
* The supervisor probes it with ``_HEALTH_TIMEOUT`` and exits for an OS
14+
restart after ``_MAX_UNHEALTHY_HEARTBEATS`` consecutive failures.
15+
16+
So the probe that decides whether to KILL the service competes for the very
17+
resource that saturation exhausts. Under indexing load the pool is contended,
18+
``/health`` blocks past the probe timeout, the counter fills, and the service
19+
is restarted — which severs in-flight clients, which makes them retry, which
20+
adds load. Self-amplifying.
21+
22+
THE DEEPER DEFECT the fix addresses: ``_service_healthy`` returned a bare bool,
23+
collapsing "answered 503" and "did not answer at all" into one False. Those are
24+
opposite pieces of evidence:
25+
26+
* 503 — the process ANSWERED. It is demonstrably alive; the DB is unhappy.
27+
Restarting cannot fix a down database and does sever clients.
28+
* timeout / refused — the process may genuinely be wedged. This is the only
29+
evidence that justifies a restart.
30+
31+
Only UNKNOWN advances the restart counter. Hal decision 2026-07-24. The
32+
correct long-term fix is a dependency-free engine liveness endpoint, queued
33+
for the v0.1.55 engine batch.
34+
"""
35+
from __future__ import annotations
36+
37+
import http.server
38+
import threading
39+
40+
import pytest
41+
42+
43+
@pytest.fixture
44+
def health_server():
45+
"""Real loopback server on port 0 whose /health status is switchable."""
46+
state = {"status": 200, "delay": 0.0}
47+
48+
class _H(http.server.BaseHTTPRequestHandler):
49+
def do_GET(self) -> None: # noqa: N802 — stdlib callback name
50+
if state["delay"]:
51+
import time
52+
53+
time.sleep(state["delay"])
54+
body = b'{"status":"ok"}'
55+
self.send_response(state["status"])
56+
self.send_header("Content-Length", str(len(body)))
57+
self.end_headers()
58+
self.wfile.write(body)
59+
60+
def log_message(self, *_a: object) -> None:
61+
pass
62+
63+
httpd = http.server.HTTPServer(("127.0.0.1", 0), _H)
64+
threading.Thread(target=httpd.serve_forever, daemon=True).start()
65+
yield httpd, state
66+
httpd.shutdown()
67+
httpd.server_close()
68+
69+
70+
def _probe(port: int):
71+
from nexus.daemon.storage_service_daemon import StorageServiceSupervisor
72+
73+
sup = StorageServiceSupervisor.__new__(StorageServiceSupervisor)
74+
sup._service_port = port
75+
return sup._probe_service_health()
76+
77+
78+
class TestProbeClassification:
79+
def test_200_is_ok(self, health_server) -> None:
80+
from nexus.daemon.storage_service_daemon import HealthProbe
81+
82+
httpd, _state = health_server
83+
assert _probe(httpd.server_address[1]) is HealthProbe.OK
84+
85+
def test_503_is_unready_not_unknown(self, health_server) -> None:
86+
"""THE fix. The service answered — it is alive. Classifying this as
87+
UNKNOWN is what let a DB blip and a load spike both kill a healthy
88+
process."""
89+
from nexus.daemon.storage_service_daemon import HealthProbe
90+
91+
httpd, state = health_server
92+
state["status"] = 503
93+
assert _probe(httpd.server_address[1]) is HealthProbe.UNREADY
94+
95+
def test_timeout_is_unknown(self, health_server, monkeypatch) -> None:
96+
"""A probe that never came back is the ONLY evidence of a wedge."""
97+
import nexus.daemon.storage_service_daemon as ssd
98+
from nexus.daemon.storage_service_daemon import HealthProbe
99+
100+
httpd, state = health_server
101+
state["delay"] = 1.5
102+
monkeypatch.setattr(ssd, "_HEALTH_TIMEOUT", 0.25)
103+
assert _probe(httpd.server_address[1]) is HealthProbe.UNKNOWN
104+
105+
def test_refused_connection_is_unknown(self) -> None:
106+
import socket
107+
108+
from nexus.daemon.storage_service_daemon import HealthProbe
109+
110+
s = socket.socket()
111+
s.bind(("127.0.0.1", 0))
112+
port = s.getsockname()[1]
113+
s.close() # nothing listening now
114+
assert _probe(port) is HealthProbe.UNKNOWN
115+
116+
def test_unset_port_is_unknown(self) -> None:
117+
from nexus.daemon.storage_service_daemon import HealthProbe
118+
119+
assert _probe(0) is HealthProbe.UNKNOWN
120+
121+
122+
class TestRestartAccounting:
123+
"""The counter must advance ONLY on UNKNOWN."""
124+
125+
def _sup(self, probe_result):
126+
from unittest.mock import MagicMock
127+
128+
import nexus.daemon.storage_service_daemon as ssd
129+
130+
sup = ssd.StorageServiceSupervisor.__new__(ssd.StorageServiceSupervisor)
131+
sup._consecutive_unhealthy_heartbeats = 0
132+
sup._service_port = 1
133+
sup._pg_port = 2
134+
sup._proc = MagicMock()
135+
sup._proc.poll.return_value = None
136+
sup._proc.pid = 4242
137+
sup._supervisor = MagicMock()
138+
sup._supervisor.fenced = False # healthy path re-stamps and checks this
139+
sup._scope = "test-scope" # only read when fenced, but keep it real
140+
sup._probe_service_health = lambda: probe_result
141+
sup._pg_reachable = lambda: True
142+
return sup
143+
144+
def test_repeated_503_never_reaches_the_restart_threshold(
145+
self, monkeypatch,
146+
) -> None:
147+
"""Steve's shape. Twenty consecutive 503s must not kill a process that
148+
answered twenty times."""
149+
import nexus.daemon.storage_service_daemon as ssd
150+
from nexus.daemon.storage_service_daemon import HealthProbe
151+
152+
monkeypatch.setattr(ssd, "_pid_is_alive", lambda _pid: True)
153+
sup = self._sup(HealthProbe.UNREADY)
154+
155+
for _ in range(20):
156+
keep_going, _pg = sup.heartbeat_once()
157+
assert keep_going, "a service answering 503 must never be killed"
158+
assert sup._consecutive_unhealthy_heartbeats == 0
159+
160+
def test_sustained_unknown_still_triggers_the_restart(
161+
self, monkeypatch,
162+
) -> None:
163+
"""The stuck-but-alive class the threshold exists for must still be
164+
caught — this fix must not disarm wedge detection."""
165+
import nexus.daemon.storage_service_daemon as ssd
166+
from nexus.daemon.storage_service_daemon import HealthProbe
167+
168+
monkeypatch.setattr(ssd, "_pid_is_alive", lambda _pid: True)
169+
sup = self._sup(HealthProbe.UNKNOWN)
170+
171+
outcomes = [
172+
sup.heartbeat_once()[0]
173+
for _ in range(ssd._MAX_UNHEALTHY_HEARTBEATS)
174+
]
175+
assert outcomes[-1] is False, "sustained no-answer must still restart"
176+
177+
def test_an_ok_beat_resets_the_counter(self, monkeypatch) -> None:
178+
import nexus.daemon.storage_service_daemon as ssd
179+
from nexus.daemon.storage_service_daemon import HealthProbe
180+
181+
monkeypatch.setattr(ssd, "_pid_is_alive", lambda _pid: True)
182+
sup = self._sup(HealthProbe.UNKNOWN)
183+
sup.heartbeat_once()
184+
assert sup._consecutive_unhealthy_heartbeats == 1
185+
186+
sup._probe_service_health = lambda: HealthProbe.OK
187+
sup.heartbeat_once()
188+
assert sup._consecutive_unhealthy_heartbeats == 0
189+
190+
191+
def test_probe_timeout_respects_the_lease_ttl_invariant() -> None:
192+
"""The probe budget is CAPPED, not free.
193+
194+
Originally this asserted ``_HEALTH_TIMEOUT >= 10.0`` on the reasoning that
195+
the probe must outlast pool contention. That was wrong and the existing
196+
invariant test caught it: the probe BLOCKS the heartbeat thread, so a tick
197+
costs ``_HEALTH_TIMEOUT + heartbeat_interval`` and the lease TTL must be at
198+
least 3x that (test_ttl_exceeds_worst_case_heartbeat_tick). A 20s probe
199+
made the supervisor's OWN lease age out mid-probe — trading a spurious
200+
restart for a vanished endpoint, which is the same outage wearing a
201+
different hat.
202+
203+
So the honest statement is: 4.0s is the largest value the current design
204+
permits, and it is NOT large enough to outlast a saturated HikariCP pool
205+
(connectionTimeout 30s). The tri-state fix stands on its own; closing the
206+
remaining gap needs the probe off the heartbeat thread or a dependency-free
207+
engine liveness endpoint. Both are tracked.
208+
"""
209+
import nexus.daemon.storage_service_daemon as ssd
210+
from nexus.daemon.service_registry import DEFAULT_HEARTBEAT_INTERVAL, ttl_for_tier
211+
212+
worst_tick = ssd._HEALTH_TIMEOUT + DEFAULT_HEARTBEAT_INTERVAL
213+
assert ttl_for_tier("storage_service") >= 3 * worst_tick, (
214+
"probe timeout raised past what the lease TTL can absorb — the "
215+
"supervisor would lose its own lease while probing"
216+
)
217+
# Still meaningfully wider than the 2s/3-beat window that cycled Steve's
218+
# service: 4 beats of total silence at ~5s per tick.
219+
assert ssd._HEALTH_TIMEOUT * ssd._MAX_UNHEALTHY_HEARTBEATS >= 16.0

0 commit comments

Comments
 (0)