3523dcf93e
plans/ held 58 documents and exactly one said whether it was open. The rest
mixed finished work, reviews of shipped work, parked specs and genuinely
pending ones, with nothing distinguishing them, so "how many plans are in
the queue" had no answer short of reading all 58.
Now `grep -H '^Status:' plans/*.md` is the answer:
50 done 3 in progress 2 planned 2 reference 1 parked
Statuses were derived rather than guessed: CLAUDE.md's own built list and
"What's NOT built yet" section, plus checking the subject exists in the
code. A review of work that shipped counts as done -- it records what was
found, it is not a request for anything. `reference` separates the two docs
that are conventions rather than work items (admin-design-standards,
admin-work-framework), which otherwise read as permanently-open plans.
The vocabulary is deliberately five words. A larger one invites "mostly
done" and "blocked-ish", which is how the directory became unreadable.
test_plans_declare_status.py keeps it from rotting: a new plan without a
marker fails, as does an unknown status, one buried below the eighth line,
or an open status with no reason -- "planned" alone is the state that rots,
since nobody can tell later whether it waits on a decision, a dependency,
or just nobody's turn.
Also updates the sweep plan with what landed and what did not, including
that #9 was not a defect.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VRQXz5SYZYVWscxS1QqF6U
213 lines
12 KiB
Markdown
213 lines
12 KiB
Markdown
# Router going unreachable under `systemctl` — investigation & hardening plan
|
|
|
|
Status: done -- docs/incidents.md
|
|
|
|
Started 2026-08-29, after the dispatcher went unreachable three times in one
|
|
session (opencode: `ConnectionError ... Connection refused`, and the TUI
|
|
showing the same). `systemctl --user status` reported `active (running)`
|
|
every time — the process never exited, it just stopped accepting
|
|
connections. Findings ranked by what's confirmed vs. still open.
|
|
|
|
---
|
|
|
|
## What's confirmed
|
|
|
|
- Each time, `journalctl --user -u llm-router.service` shows the uvicorn
|
|
process itself logging `INFO: Shutting down` / `INFO: Waiting for
|
|
connections to close. (CTRL+C to force quit)` — this is uvicorn's own
|
|
signal handler firing, i.e. the process received **SIGTERM (or SIGINT)**.
|
|
- In every occurrence there is **no preceding `Stopping Local LLM model
|
|
router...` line from `systemd[862]`**. That line is systemd's own,
|
|
unconditional announcement that *it* is running a stop job — it appears
|
|
before the two known-good causes (`systemctl stop`, `systemctl restart`,
|
|
including the ones this session ran deliberately, which do show it). Its
|
|
absence means the signal did not arrive through `systemctl`.
|
|
- Because systemd never opened a stop job for these, `TimeoutStopUSec`
|
|
(10s, systemd's default) never applied, and `Restart=on-failure` never
|
|
fired — that only triggers when the **main process exits**, and it never
|
|
did. The unit sat in `active (running)` indefinitely, fully invisible to
|
|
systemd's own health tracking, while `curl localhost:8080/health` and
|
|
`ss -ltnp` (no listener on 8080) showed it was actually dead to clients.
|
|
- `GET /admin/api/restart-service` was never hit — its access-log line
|
|
(`POST /api/restart-service`) does not appear in the journal around any of
|
|
the incidents, and that endpoint calls `systemctl --user restart`
|
|
(`admin.py:691`) which — like the manual restarts — *would* produce the
|
|
"Stopping" line. Ruled out.
|
|
- Not a suspend/resume cycle (`journalctl` around each incident has no
|
|
`suspend|resume|sleep|lid` entries) and not `systemd-oomd` (disabled on
|
|
this host, and RSS was ~100-140MB — nowhere near OOM territory).
|
|
- Once hung, the process has ~10 open sockets it's waiting to drain
|
|
(`/proc/<pid>/fd`) and its listening socket is already closed — consistent
|
|
with `_decision_event_stream()` (`dispatcher.py:1396-1415`), the
|
|
`/events/decisions` SSE generator, which is an unconditional `while True`
|
|
loop that only exits when the client disconnects. It sends a heartbeat
|
|
every `SSE_HEARTBEAT_SECONDS = 15`, so it never looks "stuck" to uvicorn —
|
|
it's actively working, just working forever. Any TUI or admin-dashboard tab
|
|
left open holds one of these connections open across a restart attempt.
|
|
- **Fix applied for the *symptom*, already shipped** (commit `b9220ed`):
|
|
`ExecStart` now passes `--timeout-graceful-shutdown 5`
|
|
(`deploy/llm-router.service`, mirrored to
|
|
`~/.config/systemd/user/llm-router.service`). This caps uvicorn's own
|
|
drain wait at 5s independent of whether systemd is tracking a stop job, so
|
|
a bare SIGTERM now converges to a clean exit instead of hanging forever.
|
|
Verified live: the process restarted under this flag has picked it up
|
|
(confirmed via `ps -o cmd` showing the flag on the running command).
|
|
|
|
## What's still open: who sends the signal
|
|
|
|
The symptom (hangs forever) is fixed. The **trigger** (something delivers
|
|
SIGTERM outside of `systemctl`) is not identified, and will keep firing every
|
|
10-20 minutes based on tonight's timeline (21:36, 21:49, 22:08, 22:23, 01:42,
|
|
01:58 — irregular, not matching either systemd timer's schedule:
|
|
`llm-router-poller.timer` is 2h, `llm-router-seed.timer` is 6h).
|
|
|
|
### H1 — Manual `kill`/`pkill`/process manager in another pane
|
|
|
|
Two of the six restarts tonight (22:23:07, 01:42:16) exactly match
|
|
`systemctl --user restart llm-router.service` in this pane's
|
|
`~/.zsh_history`. The other four don't appear in this pane's history, but
|
|
there are two other active tmux panes (pts/2, pts/3, an opencode session)
|
|
whose shell history hasn't necessarily flushed to disk yet. A `pkill -f
|
|
uvicorn`, an `htop`/`btop` kill keystroke, or a `kill <pid>` typed while
|
|
cleaning up a stale process in one of those panes would produce exactly this
|
|
signature: signal delivered, no systemd stop job.
|
|
|
|
**How to confirm, without more guessing**: `auditctl` is present on this
|
|
host but needs `sudo`, which isn't passwordless here. One-time setup (run
|
|
this yourself, since it needs your password):
|
|
|
|
```bash
|
|
sudo auditctl -a always,exit -F arch=b64 -S kill -F a1=15 -k routerkill
|
|
sudo auditctl -a always,exit -F arch=b64 -S tgkill -F a2=15 -k routerkill
|
|
```
|
|
|
|
Then after the next hang:
|
|
|
|
```bash
|
|
sudo ausearch -k routerkill -i | tail -40
|
|
```
|
|
|
|
This resolves the exact calling PID, command, and parent PID for every
|
|
SIGTERM (`a1=15`/`a2=15` is the signal-number filter) sent anywhere on the
|
|
system — it will name the culprit on the next occurrence, whether it's a
|
|
shell, a TUI keybinding, or something else entirely.
|
|
|
|
### H2 — In-process signal provenance (fallback if you'd rather not touch audit)
|
|
|
|
If `auditctl` is unwanted, the alternative is to have `dispatcher.py` itself
|
|
report who signaled it. Python's `signal.signal()` handler doesn't expose the
|
|
sender, but `signal.sigwaitinfo()` does (`si_pid`, `si_uid`) when the signal
|
|
is blocked from the default async handler and waited on synchronously. This
|
|
would mean overriding uvicorn's own SIGTERM handling — a real change to
|
|
shutdown behavior, not just an observation — so it's a fallback, not the
|
|
first move. Concretely: block SIGTERM in the main thread at startup
|
|
(`signal.pthread_sigmask`), spawn a daemon thread that blocks on
|
|
`signal.sigwaitinfo([signal.SIGTERM])`, logs `si_pid`/`si_uid`, resolves
|
|
`/proc/<si_pid>/comm` and `/proc/<si_pid>/cmdline`, and *then* re-raises
|
|
SIGTERM to itself so uvicorn's normal shutdown still runs. Only worth
|
|
building if H1's `auditctl` approach is blocked (e.g. no sudo access at all).
|
|
|
|
### H3 — A systemd timer or path unit we haven't found
|
|
|
|
Checked and ruled out: only `llm-router-poller.timer` (2h) and
|
|
`llm-router-seed.timer` (6h) reference this unit family
|
|
(`systemctl --user list-timers`), and neither's schedule lines up with any
|
|
incident tonight. No path units exist under
|
|
`~/.config/systemd/user/*.path`. Not revisiting unless H1 comes back
|
|
negative.
|
|
|
|
### H4 — opencode or its plugins
|
|
|
|
Checked `deploy/opencode-plugin/router-outcome.js` (the only opencode plugin
|
|
touching this router) — it only does `fetch(ROUTER + "/outcome")`, no process
|
|
management, no signals. The `oh-my-openagent` lsp-daemon processes
|
|
(`304864`, `502927`) are unrelated node processes with no visibility into
|
|
this service. No code path here sends a signal. Ruled out unless new
|
|
evidence surfaces.
|
|
|
|
## Recommended next step
|
|
|
|
Run the two `auditctl` commands under H1 once (needs your sudo password —
|
|
type it interactively in one of your panes, not through me). Leave them
|
|
running; they're cheap (`kill`/`tgkill` syscalls are rare in the ambient
|
|
workload of this box). Next time the router drops, `sudo ausearch -k
|
|
routerkill -i` names the sender in one shot, which turns four remaining
|
|
hypotheses into zero. Everything else in this doc is instrumentation for if
|
|
that comes back empty.
|
|
|
|
**Status: armed 2026-08-29 ~02:05 EDT**, then immediately caught a live
|
|
occurrence at 02:06:49-54. Result was a false lead, but an instructive one:
|
|
|
|
```
|
|
type=SYSCALL msg=audit(08/29/2026 02:06:54.260:103) : arch=x86_64
|
|
syscall=tgkill success=yes exit=0 a0=0x81d9a a1=0x81d9a a2=SIGTERM ...
|
|
ppid=862 pid=531866 ... comm=uvicorn exe=/usr/bin/python3.14 key=routerkill
|
|
```
|
|
|
|
`a0`/`a1` both decode to `531866` — the process's own PID. This is **not**
|
|
an external actor. It's uvicorn's own shutdown machinery
|
|
(`.venv/.../uvicorn/server.py:315-338`, `capture_signals()`): its custom
|
|
SIGTERM handler only sets flags, so after graceful shutdown completes it
|
|
deliberately re-delivers the same signal to itself via
|
|
`signal.raise_signal()` so the process actually terminates the normal way.
|
|
Confirmed by timing: `"Shutting down"` first logged at `02:06:49`; this
|
|
self-raise is at `02:06:54` — exactly `--timeout-graceful-shutdown 5` later.
|
|
This self-raise happens at the end of **every** signal-triggered shutdown,
|
|
including ordinary `systemctl restart`s, so on its own it proves nothing
|
|
about the trigger.
|
|
|
|
The real question is what delivered the *original* SIGTERM at `02:06:49`.
|
|
Searched the full window (`-ts 02:00:40 -te 02:08:00`, both `kill` and
|
|
`tgkill`, system-wide) and found **only the one self-raise record** — no
|
|
external `kill`/`tgkill` syscall anywhere in that window. So the original
|
|
delivery didn't go through either of those two syscalls. Extended the watch
|
|
to the other three ways Linux can deliver a signal:
|
|
|
|
```bash
|
|
sudo auditctl -a always,exit -F arch=b64 -S pidfd_send_signal -F a1=15 -k routerkill
|
|
sudo auditctl -a always,exit -F arch=b64 -S rt_sigqueueinfo -F a1=15 -k routerkill
|
|
sudo auditctl -a always,exit -F arch=b64 -S rt_tgsigqueueinfo -F a2=15 -k routerkill
|
|
```
|
|
|
|
`pidfd_send_signal` is the leading suspect — it's the modern, race-free
|
|
signal syscall some tools (and some systemd internals) now prefer over the
|
|
classic `kill`/`tgkill`, and it wouldn't have matched either of the first two
|
|
rules. Next occurrence: search all five keys, not just two, and specifically
|
|
look for a record **before** the self-raise (which will always be ~5s after
|
|
the `"Shutting down"` log line and should now be treated as noise, not
|
|
signal).
|
|
|
|
**Status: all 5 rules armed 2026-08-29 ~02:13 EDT** (confirmed via `sudo
|
|
auditctl -l`). A silent occurrence at `02:12:33` (self-healed by
|
|
`Restart=always` before anyone noticed — `Shutting down` at `02:12:33`, back
|
|
up at `02:12:43`) landed 25 seconds *before* the 3 new rules were added
|
|
(`CONFIG_CHANGE` records at `02:13:04`), so it's an incomplete but useful
|
|
data point: `sudo ausearch -k routerkill -i` for that window shows plenty of
|
|
unrelated `kill` traffic (a `timeout 5 curl` test artifact at `02:10:50`; a
|
|
Chrome thread pool killing its own subprocesses at `02:12:23`, none of them
|
|
targeting the router's PID) and the expected self-raise at `02:12:38`
|
|
(target `532910`, confirming which MainPID this crash belonged to) — but
|
|
**no `kill`/`tgkill` record anywhere delivering to `532910`/`0x821ae`
|
|
itself.** So the original delivery for this occurrence definitely didn't use
|
|
either of the first two watched syscalls, which is exactly what the
|
|
`pidfd_send_signal` hypothesis predicts. That rule (plus the two
|
|
`rt_*sigqueueinfo` ones) simply wasn't armed yet for this one. Waiting on
|
|
the next occurrence now that all 5 are live.
|
|
|
|
When it happens: `sudo ausearch -k routerkill -i` and look for a record
|
|
targeting the router's PID that is *not* ~5s after the "Shutting down" log
|
|
line (that offset is always the harmless uvicorn self-raise) and *not*
|
|
`comm=uvicorn` — that's the real sender.
|
|
|
|
**Interim mitigation shipped regardless of root cause**: `Restart=on-failure`
|
|
→ `Restart=always` in `llm-router.service` (both the live unit and
|
|
`deploy/llm-router.service`). Systemd's `on-failure` policy explicitly
|
|
excludes clean termination by SIGTERM/SIGINT from auto-restart (its
|
|
assumption: SIGTERM means someone deliberately asked it to stop). That
|
|
assumption was wrong for these events, and combined with the graceful-
|
|
shutdown-timeout fix (the process now exits cleanly *instead of* hanging),
|
|
it meant every occurrence left the service `inactive (dead)` until a human
|
|
noticed and restarted it by hand. `Restart=always` self-heals within
|
|
`RestartSec=5s` for any termination *except* an explicit `systemctl stop`,
|
|
which systemd still honors correctly regardless of the Restart= policy.
|