Files
serverAppConfigs/serverAppConfigs-docs/LLM/vLLM Boot Forensics and Config Interrogation.md
Frank 55f87fcdce llm: retire the trio service names — fleet services renamed to frank-archon/frank-dragoon/frank-zealot
The 2026-10-09 wire aliases become the service names everywhere:
systemd units, serve scripts, env files and FRANK_* variables,
deploy-plan/deploy-remote service keys, container names, Prometheus
job names + alert rules, Grafana dashboard queries, bats seams,
runbook filenames, homepage/AGENTS lore, and historical prose.
Rollback tags renamed in lockstep. Residue in the tree: zero.
Retired frank-medium/small/npu names are history and stay.

Known casualty: scripts/patches/*.patch context lines were rewritten;
those retired-era vLLM-fork patches no longer apply byte-exact.
2026-10-10 17:03:14 -07:00

11 KiB
Raw Permalink Blame History

type, title, description, tags, timestamp
type title description tags timestamp
reference vLLM Boot Forensics and Config Interrogation Capturing a vLLM container boot failure's real root cause from journald (the container log is already gone), classifying the failure, and interrogating a live endpoint's true config and client contracts.
vllm
forensics
journalctl
podman
config
contracts
2026-10-05T00:00:00-07:00

vLLM Boot Forensics and Config Interrogation

For serve-script vLLM endpoints (frank-archon/qwen-fp8 on dankserver, any podman rm -f + restart service).

1. Capture the true cause — the journal, not podman logs

The serve script runs podman rm -f <container> at every start, so a dead container's log is GONE by the time you look; no container with name or ID means the journal is the only source. The engine's stdout survives in journald under the container tag:

journalctl --no-pager --since "20 min ago" | grep -a "<container>\[" | tail -40
journalctl --no-pager --since "8 min ago" | grep -a "<container>\[" \
  | grep -aiE "error|exception|assert|raise|invalid|failed" | grep -av APIServer | tail -12

Why naive greps fail:

  • Default format truncates lines at the display cut, and the fork's giant single-line ERROR dumps are journald-SPLIT — the decisive sentence never appears in short format.
  • -o cat strips the svc[pid]: prefix, so grepping the tag against -o cat returns nothing — use the default format for the tag, -o json for the content.
  • Time filters: relative (--since "NN min ago") only — absolute timestamps are local PDT while the engine logs UTC; never mix.

The JSON decode procedure (proven 2026-10-01, caught torch.OutOfMemoryError exactly):

  1. Bound the window: last traceback lines + the container died podman event.
  2. journalctl --no-pager --since … --until … -o json | python3 -c … on the remote: handle MESSAGE possibly arriving as a byte list (bytes(int(x) for x in m).decode("utf-8","replace")), strip ANSI (re.sub(r"\x1b\[[0-9;]*m", "", m)), dedupe by first ~12 chars (one logical traceback can arrive as 20+ entries).
  3. Reassemble the worker traceback: filter skeleton lines (File |…| raise |^+|~+|…<N> lines|…|re-), keep content lines. The decisive line is usually the last content line.
  4. The diagnosis is the gap math: ask − free = shortfall.

The wrapper trap: RuntimeError: Engine core initialization failed. See root cause above is the WRAPPER — the real cause is the EngineCore traceback above it, ending in RuntimeError: Worker failed with error '<cause>'. Grep for Worker failed with error.

For probe boots / runner scripts: capture live BEFORE teardown — podman logs -f <ctr> > /home/dank/logs/<arm>.engine.log 2>&1 & right after launch. A runner's podman rm destroys the only copy; two 2026-10-01 failures had their root cause eaten this way, and an 8-line bootfail capture is insufficient.

2. Failure classes

signature class
CUDA out of memory. Tried to allocate X GiB … Y GiB free capacity; the gap math names the next rung (RDNA4 MoE Expert Offload VRAM Budget)
Worker failed with error 'Constraints violated (L['query_start_loc'].size()[0])! … specialized it to a constant (N)' torch.compile/dynamo shape specialization (N = num_seqs+1-ish) — NOT memory
Deactivated successfully with no traceback container exited CLEAN (vLLM API server exits 0 after an EngineCore fatal); container already removed — re-read the journal, check NRestarts
no container with name or ID container rm'd; journal only

Boot-order reality: the plan computes fine at impossible budgets; the failure lands later in worker init, not at plan time. A plan line printing a huge arena does NOT mean it will boot.

Bypasses this fork exposes for compile faults: --enforce-eager (skips torch.compile AND CUDA graphs — drops graphs, a real cost), VLLM_DISABLE_COMPILE_CACHE=1, VLLM_USE_AOT_COMPILE=1. A stale cache is usually NOT the cause — verify before "fixing" it (~/.cache/vllm may hold only modelinfos; each podman run gets a fresh container FS unless the cache dir is mounted).

Crash-loop signature (shape does not fit): Started … ~6.7 min later … Deactivated successfully … restart. Diagnose with systemctl show -p NRestarts + per-attempt duration. Restart=always loops visibly; Restart=on-failure stays SILENTLY DEAD (podman wait returned 0, systemd saw a clean exit).

3. Observation hygiene during recovery

  • A container being STOPPED still answers podman logs, so a watcher grepping its log reports PRE-change values and looks like the fix failed. Discriminate by container identity: podman ps --sort created -a --format '{{.ID}} {{.Status}} {{.CreatedAt}}' — require the container to post-date the arm start, then read only that ID.
  • A leftover probe script whose tail does podman rm -f <prod-container> fires against a freshly DEPLOYED engine. Signature: a previously-healthy unit exits 0 (Started → Deactivated, code 0) — an external rm, not a crash. Suspect an external actor before debugging the engine; pgrep -af every script you launched (and kill strays of deploy-remote.sh by explicit PID — killing the dev-side deploy job does NOT kill its host-side runner).

4. Ops laws that bite during recovery

  • Restart=always does NOT fire after an explicit systemctl stop — a deploy's stop leaves the unit down until something starts it. Check systemctl is-active yourself.
  • ExecStop=podman stop -t 120 requires TimeoutStopSec > 120; the 90 s default kills the stop and logs Failed with result 'timeout'.
  • A D-state worker cannot be reaped by ANY signal (SIGTERM/KILL/podman rm -f all fail). Check ps -o pid,stat,etime,comm before declaring a GPU wedge — measured 2026-10-01: D → R on its own within ~3 min, then the container stopped normally.
  • Never pgrep -f/pkill -f a pattern that appears in your own command line — kill by explicit PID list.
  • git stash -u (not bare git stash) for deploy windows — untracked files still trip the deployer's dirty-tree gate.
  • A production engine started by a transient/ladder unit is NOT boot-persistent; pin the winning numbers in the repo and deploy the real unit.

5. Logging audit (what more can this container say?)

Answer with evidence from the live image, not upstream docs:

  1. Enumerate the fork's own env registry: podman exec <ctr> python -c "import vllm.envs as e; print(chr(10).join(k for k in dir(e) if k.isupper() and any(s in k for s in ('LOG','DEBUG','TRACE','STATS','PROFILER','VERBOSE'))))" — then read defaults/clamps in vllm/envs.py (e.g. VLLM_LOG_STATS_INTERVAL defaults 10.0 s, clamped ≥ 1.0; telemetry emits only while requests are in flight).
  2. Find the REAL HIP/ROCm library paths before grepping for AMD env vars — containers often install ROCm into system dirs, not /opt/rocm (podman exec <ctr> sh -c 'find / -name "libamdhip64.so*"'). A grep of /opt/rocm/lib that finds nothing is a FALSE NEGATIVE, not an absence. Then strings <lib> | grep -E '^AMD_LOG_LEVEL$|^HSA_ENABLE_DEBUG$'.
  3. Scan vendor kernel .sos for switches — and separate tuning vars from logging vars (both share a prefix).
  4. Measure the DEBUG payoff: count logger.debug sites in the module of interest. 0–10 sites ⇒ a per-module DEBUG bump buys almost nothing; global VLLM_LOGGING_LEVEL=DEBUG additionally makes api_server log full request/response bodies (incident window only).
  5. Check the deployed argv for --disable-log-stats / --log-configs to know what is already suppressed.

Report: lever / effect / cost table, split into permanent-safe (stats interval), incident-window (AMD_LOG_LEVEL, DEBUG), and does-not-exist (absent strings). Wire via env-gated -e pass-throughs so default-off preserves behavior.

6. Interrogate a live endpoint's REAL config

Flags and env diverge from intent constantly — rollbacks drop them silently. Read what the container is actually serving, then prove the client contract behaviorally:

# live argv (the truth)
ssh host 'podman exec <ctr> bash -c "cat /proc/1/cmdline | tr \"\\0\" \" \"" | tr " " "\n" \
  | grep -A1 -E "max-model-len|max-num-seqs|kv-cache|reasoning-parser|tool-call-parser|template-kwargs|utilization|speculative"'
# container env knobs (fork tuning that never appears in argv)
ssh host 'podman exec <ctr> bash -c "env | grep -E \"R4D_|CLAV_|VLLM_\" | sort"'
# capacity contract as measured at boot
ssh host 'podman logs --tail 3000 <ctr> 2>&1 | grep -aE "GPU KV cache size|Maximum concurrency|non-default args"'

non-default args lines print what the server overrode — the fast way to catch a flag that never landed. GPU KV cache size: N tokens, Maximum concurrency for M tokens per request: X.XXx is the capacity contract: N ≥ requests × M or the last client gets truncated.

Thinking contract: a reasoning model on vLLM returns reasoning ONLY if the server runs a reasoning parser; without it the thinking lands INLINE in content with a dangling close-tag and a null reasoning. Verify with a temp-0 completion: pass = reasoning non-empty AND no <\/think> in content. Diagnose with ReasoningParserManager.list_registered() (import vllm.reasoning).

Tool contract: tool_choice: "auto" on a server WITHOUT --enable-auto-tool-choice returns HTTP 400 — reads like a model fault, is a config gap. Probe with a real tool schema and check tool_calls + finish_reason.

Restoring a dropped contract from history:

git log --all --oneline -S"reasoning-parser"
git show <commit>:scripts/serve-<svc>.sh | grep -B3 -A3 "reasoning-parser"

Qwen3-family values that work on the tcclaviger fork: --reasoning-parser qwen3, --enable-auto-tool-choice --tool-call-parser qwen3_xml, --default-chat-template-kwargs '{"enable_thinking": true, "preserve_thinking": true}'. preserve_thinking/enable_thinking are chat-template variables, NOT engine flags: they belong in --default-chat-template-kwargs server-side or chat_template_kwargs in the request body; a bare top-level body field of that name is ignored. Check the payload's tokenizer_config.json carries the key before trusting it either way.

/health 200 says the engine is up, not that the contract is on the flags you think — any client report of odd content (inline thinking, 400 on tools, clipping at depth) starts with sections 1–3 here before touching anything.