Host controller wedges with a frozen heartbeat while the control plane and doctor still report healthy (two occurrences on 2026-09-04)

[kyle-sexton]

Summary

The host controller (v0.1.24, melo-lap-001) wedged twice within 13 hours. Both times the process stayed alive and the control plane kept answering host status, but the reconcile loop stopped: observed.heartbeatAt froze, no worker was created or retired, and every job for melodic-ubuntu-24.04-x64 sat queued at GitHub while GitHub's own status page reported all systems operational.

Evidence

Wedge 1 (2026-09-04 01:03Z to 01:53Z, PID 14732, uptime about 24 h):

• host status --json: controller.phase=ready, observed.heartbeatAt=2026-09-04T01:03:14Z for 50 minutes; three workers reported (idle, busy, busy) while docker ps showed zero ci-runner-* containers. Worker log for dl64halo74o4-2v8 ends at 01:03:30Z with a clean Runner listener exit with 0 return code.
• Process had consumed about 126,899 CPU-seconds over its lifetime (~1.4 cores continuously). host controller restart hung 240 s waiting for the drain confirmations the dead loop never produced. taskkill /F plus schtasks /Run /TN ci-runner-fleet recovered it; first fresh heartbeat 01:57:36Z, queue drained within two minutes.

Wedge 2 (2026-09-04, PID 206652 from 01:53Z, then PID 89152 after a graceful restart at 13:54Z):

• From about 13:40Z GitHub stopped assigning queued jobs to the scale set although four workers were idle, capacityAcknowledged=true, maxCapacity=11, totalAssignedJobs=0; 17 github-iac jobs queued for 12 minutes. Controller log in that window shows only worker-retirement-zero-stability-unconfirmed (x10), worker-removal-capacity-stale (x9), one runner-registration-missing, one unregistered-worker-became-busy.
• host controller restart completed cleanly this time (capacity-zero drain accepted, exit code 75, receipt verified, replacement PID 89152 started 13:54:51Z).
• The replacement never left phase=disabled although desired.mode=enabled: observed.heartbeatAt stayed at 13:54:49Z for 9+ minutes, both listeners at capacity=0, zero workers, controller log contains only the controller-started line. Process CPU: 11.05 s in a 10 s window (busy loop), 23 threads, 148 MB, and the only TCP connection was the local OTEL exporter on 127.0.0.1:4317 (no GitHub or Docker API traffic). host enable --wait hung 180 s. host doctor reported every check PASS except the advisory pending-OS-reboot WARN.

Host: Windows 11 Pro 26200, Docker Desktop responsive throughout (docker version/docker info under 1 s), AC power, 37 GiB free memory, host CPU otherwise idle.

Fix

Unknown; needs the reconcile loop's own diagnostics. Suggested first steps:

1. Make the loop's liveness observable: a stall of observed.heartbeatAt beyond reconcileInterval x N should be surfaced by host doctor as a FAIL, not PASS (it showed PASS with age=2m17s maximumAge=26m10s while the loop was already dead).
2. Capture a goroutine dump (or the equivalent) on host controller restart timeout and on a heartbeat stall, written under diagnostics/.
3. Check the startup path for a busy-wait: the replacement process spun at ~1 core with no network activity and no log lines after controller-started.

Verification

• A controller that has stalled for longer than the documented threshold is reported by host doctor as FAIL with the stall age.
• A diagnostic archive exists for each stall and names the blocked goroutine or loop.

Related

• Wedge 1 recovery commands and timings are recorded in the operator's session notes for 2026-09-04.
• Config: %LOCALAPPDATA%\ci-runner\config.yaml (schemaVersion 2, reconcileInterval: 5s, startupTimeout: 2m, power.policy: ac-only).

[kyle-sexton]

Additional evidence from the 14:05Z relaunch (PID 58404):

• The replacement did progress, but slowly: controller-started at 14:05:07Z, first observed.json heartbeat at 14:08:32Z (about 3.5 minutes), during which host status --json kept returning the previous process's frozen snapshot (phase=disabled, heartbeatAt=13:54:49Z) and the process burned about 0.7 core with no GitHub traffic.
• State directory sizes at that moment: jobs.json 8,387,632 bytes (records array, schemaVersion 1), runner-assign-times.json 1,872,655 bytes, plus 3,225 log entries and 6,407 diagnostics entries. If the reconcile loop re-reads and re-serialises jobs.json on every 5 s tick, that alone would explain both the sustained CPU burn and the multi-minute startup, and it grows without bound. Worth checking whether jobs.json is ever compacted.

[kyle-sexton]

This was generated by AI during triage.

Triage lane claiming this item for the current cycle (instance vm-triage-202609050304). Lease TTL 60 minutes, expires 2026-09-05T04:09:00Z. Claim covers classification and brief-authoring only — this lane does not author fix PRs or merge.

---

Generated by Claude Code

[kyle-sexton]

This was generated by AI during triage.

Triage: confirmed real; one of the three defects here is fully root-caused, the wedge itself is not

Verified against 01594bd (default branch). This issue bundles three separable defects with different owners, different evidence needs, and very different readiness. Recommending a split, detail below.

Defect A — host doctor reports PASS while the reconcile loop is dead (ROOT-CAUSED)

This is the "doctor showed PASS with age=2m17s maximumAge=26m10s while the loop was already dead" observation, and the cause is a single conflated threshold.

internal/app/doctor.go:79 sizes the heartbeat freshness limit with observedFreshnessLimit, which is (doctor.go:322):

saturatingFreshnessDuration(
    cfg.GitHub.RequestTimeout.Duration,
    cfg.GitHub.Retry.Maximum.Duration,
    cfg.Controller.ReconcileInterval.Duration,
    saturatingMulInt(max(cfg.GitHub.Retry.MaxAttempts, 1), max(len(cfg.GitHub.Targets), 1)),
)

That budget is (requestTimeout + retryBackoff) × (maxAttempts × targets) + 2 × reconcileInterval — a worst-case GitHub round-trip budget, which is why it inflates to ~26 minutes. It is then used to answer a completely different question: is the reconcile loop alive? With reconcileInterval: 5s, a totally dead loop reads "fresh" for 26 minutes.

Those are two distinct thresholds and should not share a value. Loop liveness is a local property (reconcileInterval × small N, seconds) and has nothing to do with how slow GitHub might be. The GitHub budget legitimately governs capacity-acknowledgement staleness, not heartbeat liveness.

• This defect is scoped, well-understood, and independently valuable — it converts every future occurrence from "silent stall the operator finds by hand" into a FAIL with a stall age, which is also what makes defects B and C diagnosable.
• Verification is exactly the issue's own stated bar: a controller stalled beyond the threshold is reported FAIL with the stall age.
• Caution for whoever implements it: do not simply tighten observedFreshnessLimit, since other call sites depend on the GitHub-derived budget. Add a separate liveness threshold.

Defect B — the wedge itself (NOT root-caused; needs evidence that does not exist yet)

The reconcile loop stops while the process stays alive and the control plane keeps answering. Nothing in the source read so far explains this, and it is not reproducible from the repository: it is a Windows-host, timing-dependent hang observed twice on melo-lap-001. An agent cannot reproduce this. The blocking requirement is the issue's own suggested step 2 — a goroutine dump on heartbeat stall and on host controller restart timeout, written under diagnostics/. Until that lands and catches one occurrence, any fix would be speculation.

Recommend treating "capture a goroutine dump on stall/timeout" as its own small, delegable work item, and keeping the wedge diagnosis blocked on it. Note the ordering: Defect A's FAIL condition is the natural trigger for that dump, so A should land first.

Defect C — the slow/spinning startup (LIKELY A DUPLICATE OF #328)

The replacement process burning ~0.7-1 core with no GitHub or Docker traffic and taking 3.5 minutes to first heartbeat is very probably not a separate busy-wait bug. Per the follow-up comment here, jobs.json was 8,387,632 bytes and runner-assign-times.json 1,872,655 bytes.

Triage of #328 confirmed in source that FileStore.Upsert (internal/jobindex/file_store.go:158) commits unconditionally — no equality check — and that its AfterReplace hook (file_store.go:336) rewrites the assign-times sidecar on every commit. Merge (catalog.go:74) stamps UpdatedAt = now unconditionally, so no patch is ever a no-op. With one Upsert per worker per tick, that is roughly 12 MiB/s of encode-fsync-rename churn with nothing assigned.

The question raised in the follow-up comment — "worth checking whether jobs.json is ever compacted" — has an answer: encodeWithinCapacity (file_store.go:361) compacts only under capacity pressure against the 8 MiB maximumJobState cap, by dropping tombstoned then completed records. It is a ceiling enforcer, not a retention policy. That is why the file has sat pinned at ~8 MiB for seven weeks rather than growing past it.

Recommend closing C into #328 rather than tracking it twice. If #328's fix lands and startup is still multi-minute, reopen it as its own item with fresh evidence.

Recommended split

Sub-item	Class	Ready?
A — separate loop-liveness threshold from the GitHub retry budget; doctor FAIL with stall age	work-class: scoped	Yes, agent-ready once approved
B — goroutine dump on stall / restart timeout, then diagnose the wedge	scoped (capture) → unknown (diagnosis)	Capture yes; diagnosis blocked on evidence
C — startup latency and idle CPU	duplicate	Fold into #328

I have not created sub-issues; decomposition of a live incident report is the reporter's call, and B's scope depends on what the dump should contain.

Classification of this issue as it stands

• Real: yes. Two occurrences with timestamps, PIDs, log excerpts, and recovery steps.
• Priority: priority: critical. Every job for melodic-ubuntu-24.04-x64 sat queued at GitHub across both windows and recovery required taskkill /F plus a manual scheduled-task run. Twice in 13 hours. This is a full CI stall for that runner label with no automatic recovery, and Defect A means it is currently invisible to monitoring.
• Gate: needs-human. Not delegable as a single unit — Defect B needs host-side evidence only the operator can capture, and the split above needs the reporter's sign-off. Defect A alone is agent-ready and could be lifted to agent-ready the moment it is split out.

No fix PR opened; this lane classifies and briefs only.

---

Generated by Claude Code

[kyle-sexton]

This was generated by AI during triage.

Triage lane releasing its claim (instance vm-triage-202609050304). Item is triaged and briefed; labels applied: priority: critical, work-class: scoped, status: needs-decision, needs-human. Blocked on sign-off for the three-way split above, and Defect B additionally on host-side goroutine-dump evidence.

---

Generated by Claude Code