fix: sshExec had no timeout — a hung remote command blocked forever

Root cause of "running for 10+ minutes without stopping": a real production execution (TypeType pct_create) was found genuinely stuck 17+ minutes into a single blocking SSH call. The container's post_install script was looping on `getent hosts deb.debian.org`, waiting on a network that could never come up — the operator's static IP config used gw:192.168.8.1, but the actual gateway on that subnet is 192.168.8.2, so every network call hung instead of failing fast (packets dropped, not rejected). Two compounding bugs made this unrecoverable without manual intervention: 1. sshExec (both internal/httpapi/phase3.go and internal/mcp/server.go) had NO execution timeout — `session.CombinedOutput()` blocks until the remote command exits, with no deadline. A hung remote process blocks the Go goroutine forever; the execution can never leave 'running', and the operator has no way to make it stop. Fixed: both now race the SSH call against a 10-minute hard timeout, closing the session/client and returning a clear "timed out after 10m0s" error if exceeded. (The mcp/server.go copy also still had the original "swallowed non-zero exit" bug from before that fix was applied to httpapi's copy only — fixed here too.) 2. provisionScript's DNS-wait loop assumed `getent hosts` fails fast on no connectivity — it doesn't; a black-holed network can make each call hang far past the resolver's nominal timeout, so the documented "~90s" budget was never real. Wrapped every attempt in `timeout 3` so the wall-clock budget is now actually enforced (~2min worst case), and the failure message now suggests checking the net0 gateway. Also fixes the matching UI-side gap (operator's literal question: "is there a way to get more details? it has been running for 10+ minutes without stopping"): - InlineApproval's track() polling loop had its own ~6min ceiling and simply STOPPED polling after that — silently going stale before the backend (now correctly capped at 10min) could ever resolve. Raised to a 14min ceiling with margin, and added a distinct 'stalled' state if that's ever exceeded (explicitly says something's wrong, rather than freezing silently). - The running-card now shows live elapsed time (ticking, from the execution's created_at), the actual command being run, and the execution ID — previously just a static "this can take a minute" with zero information. Also added command display to the destructive pending- approval card for full transparency before confirming. Verified live end-to-end in a real browser (dev server proxying to production): queued a real command via chat, approved via the button, watched the elapsed-time counter tick in real time, and saw it transition to a completed card with real output once the command finished. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
2026-07-10 10:45:47 +02:00
parent f936098364
commit 8950bada44
4 changed files with 188 additions and 39 deletions
--- a/internal/httpapi/phase3.go
+++ b/internal/httpapi/phase3.go
@@ -69,6 +69,14 @@ func initSSH() {
 	}
 }

+// sshExecTimeout bounds how long a single remote command may run. Without
+// this, a hung remote command (e.g. a piped install script stuck retrying
+// DNS against a misconfigured gateway) blocks the executing goroutine
+// forever: the execution never leaves 'approved'/'running', the operator
+// sees an unkillable spinner, and get_execution_status has nothing new to
+// report. Generous enough for a real apt/docker install; not infinite.
+const sshExecTimeout = 10 * time.Minute
+
 func sshExec(ctx context.Context, host, user, command string) (string, error) {
 	initSSH()
 	if len(_sshKey) == 0 {
@@ -103,19 +111,44 @@ func sshExec(ctx context.Context, host, user, command string) (string, error) {
 	}
 	defer session.Close()

-	out, err := session.CombinedOutput(command)
-	text := strings.TrimSpace(string(out))
-	// A non-zero exit MUST surface as an error. The previous guard only
-	// errored when there was no output, so a `pct create` that printed
-	// "CT 132 already exists" and exited non-zero was reported as success —
-	// the execution was marked completed though nothing was provisioned.
-	if err != nil {
-		if text != "" {
-			return text, fmt.Errorf("%w: %s", err, text)
-		}
-		return text, fmt.Errorf("exec: %w", err)
+	type result struct {
+		out []byte
+		err error
+	}
+	done := make(chan result, 1)
+	go func() {
+		out, err := session.CombinedOutput(command)
+		done <- result{out, err}
+	}()
+
+	select {
+	case r := <-done:
+		text := strings.TrimSpace(string(r.out))
+		// A non-zero exit MUST surface as an error. The previous guard only
+		// errored when there was no output, so a `pct create` that printed
+		// "CT 132 already exists" and exited non-zero was reported as
+		// success — the execution was marked completed though nothing was
+		// provisioned.
+		if r.err != nil {
+			if text != "" {
+				return text, fmt.Errorf("%w: %s", r.err, text)
+			}
+			return text, fmt.Errorf("exec: %w", r.err)
+		}
+		return text, nil
+	case <-time.After(sshExecTimeout):
+		// Close the session/client to hang up the remote side; the
+		// goroutine above will eventually exit once that unblocks
+		// CombinedOutput, but we don't wait for it — the caller needs an
+		// answer now, not an indefinite hang.
+		session.Close()
+		client.Close()
+		return "", fmt.Errorf("timed out after %s waiting for command to finish on %s", sshExecTimeout, host)
+	case <-ctx.Done():
+		session.Close()
+		client.Close()
+		return "", ctx.Err()
 	}
-	return text, nil
 }

 func resolveHostSSH(ctx context.Context, pool *db.Pool, entitySlug string) (string, string, error) {
@@ -526,11 +559,19 @@ func provisionScript(pkgs []string, postInstall string) string {
 	b.WriteString("export LANG=C.UTF-8 LC_ALL=C.UTF-8 DEBIAN_FRONTEND=noninteractive\n")
 	b.WriteString("probe=deb.debian.org\n")
 	b.WriteString("ok=0\n")
-	b.WriteString("for i in $(seq 1 30); do if getent hosts \"$probe\" >/dev/null 2>&1; then ok=1; break; fi; sleep 2; done\n")
+	// `timeout 3` on every getent call is load-bearing, not cosmetic: when
+	// the network is truly unreachable (e.g. a wrong gateway), a plain
+	// `getent hosts` doesn't fail fast — it can hang far longer than the
+	// resolver's nominal timeout because packets are just dropped, not
+	// rejected. Without a hard per-attempt cap, this loop's "~90s" budget
+	// was fiction — one run hung 17+ minutes on a bad gateway before the Go
+	// side finally got a hard sshExec timeout to fall back on. Capping each
+	// attempt makes the wall-clock budget real.
+	b.WriteString("for i in $(seq 1 30); do if timeout 3 getent hosts \"$probe\" >/dev/null 2>&1; then ok=1; break; fi; sleep 2; done\n")
 	// Self-heal: if the assigned resolver can't resolve, fall back to public DNS.
 	b.WriteString("if [ \"$ok\" != 1 ]; then printf 'nameserver 1.1.1.1\\nnameserver 8.8.8.8\\n' > /etc/resolv.conf; ")
-	b.WriteString("for i in $(seq 1 15); do if getent hosts \"$probe\" >/dev/null 2>&1; then ok=1; break; fi; sleep 2; done; fi\n")
-	b.WriteString("if [ \"$ok\" != 1 ]; then echo 'ERROR: container has no DNS/connectivity after ~90s'; exit 1; fi\n")
+	b.WriteString("for i in $(seq 1 15); do if timeout 3 getent hosts \"$probe\" >/dev/null 2>&1; then ok=1; break; fi; sleep 2; done; fi\n")
+	b.WriteString("if [ \"$ok\" != 1 ]; then echo 'ERROR: container has no DNS/connectivity after ~2min — check the LXC net0 gateway/IP are correct for this subnet'; exit 1; fi\n")
 	b.WriteString("set -e\n")
 	if len(pkgs) > 0 {
 		b.WriteString("export DEBIAN_FRONTEND=noninteractive\n")
--- a/internal/mcp/server.go
+++ b/internal/mcp/server.go
@@ -1048,6 +1048,12 @@ func initSSH() {
 	}
 }

+// sshExecTimeout bounds how long a single remote command may run — see the
+// matching constant/comment in httpapi/phase3.go. Without it, a hung remote
+// command (piped install script stuck retrying DNS, etc.) blocks this
+// goroutine forever with no way for the caller to ever get an answer.
+const sshExecTimeout = 10 * time.Minute
+
 func sshExec(ctx context.Context, host, user, command string) (string, error) {
 	initSSH()
 	if len(sshKey) == 0 {
@@ -1082,11 +1088,40 @@ func sshExec(ctx context.Context, host, user, command string) (string, error) {
 	}
 	defer session.Close()

-	out, err := session.CombinedOutput(command)
-	if err != nil && out == nil {
-		return "", fmt.Errorf("exec: %w", err)
+	type result struct {
+		out []byte
+		err error
+	}
+	done := make(chan result, 1)
+	go func() {
+		out, err := session.CombinedOutput(command)
+		done <- result{out, err}
+	}()
+
+	select {
+	case r := <-done:
+		text := strings.TrimSpace(string(r.out))
+		// A non-zero exit MUST surface as an error — matching the fix
+		// applied to httpapi's sshExec (this copy still had the original
+		// bug: only erroring when there was no output at all, so a command
+		// that failed but printed something was silently reported as
+		// success).
+		if r.err != nil {
+			if text != "" {
+				return text, fmt.Errorf("%w: %s", r.err, text)
+			}
+			return text, fmt.Errorf("exec: %w", r.err)
+		}
+		return text, nil
+	case <-time.After(sshExecTimeout):
+		session.Close()
+		client.Close()
+		return "", fmt.Errorf("timed out after %s waiting for command to finish on %s", sshExecTimeout, host)
+	case <-ctx.Done():
+		session.Close()
+		client.Close()
+		return "", ctx.Err()
 	}
-	return strings.TrimSpace(string(out)), nil
 }

 func resolveHost(ctx context.Context, pool *db.Pool, entitySlug string) (hostIP string, sshUser string, err error) {
--- a/web/src/lib/components/InlineApproval.svelte
+++ b/web/src/lib/components/InlineApproval.svelte
@@ -13,7 +13,7 @@
  // Per-execution UI phase, keyed by executionId. A resolved phase hides the
  // action buttons permanently so the banner clears after a click and can
  // never re-POST /decision.
-  type Phase = 'deciding' | 'running' | 'completed' | 'failed' | 'denied'
+  type Phase = 'deciding' | 'running' | 'completed' | 'failed' | 'denied' | 'stalled'
  const phase = new SvelteMap<string, Phase>()
  // Latest execution row (for status/result display), keyed by executionId.
  const exec = new SvelteMap<string, Execution>()
@@ -32,10 +32,40 @@
    return typeof v === 'string' ? v.trim() : ''
  }

+  function elapsedSeconds(e: Execution | undefined): number | null {
+    if (!e?.created_at) return null
+    return Math.max(0, Math.round((now - new Date(e.created_at).getTime()) / 1000))
+  }
+
+  function fmtDuration(s: number): string {
+    if (s < 60) return `${s}s`
+    const m = Math.floor(s / 60)
+    return `${m}m ${s % 60}s`
+  }
+
+  // Live clock for the elapsed-time display on running cards. Tied to
+  // component lifecycle via $effect so the interval is guaranteed cleared on
+  // unmount — a bare setInterval field here would leak a 1Hz timer for the
+  // lifetime of the page every time this component was mounted.
+  let now = $state(Date.now())
+  $effect(() => {
+    const t = setInterval(() => { now = Date.now() }, 1000)
+    return () => clearInterval(t)
+  })
+
+  // Backend commands are hard-capped at 10 minutes (internal sshExec
+  // timeout) before the execution is force-finalized as failed — so polling
+  // must outlast that with margin, or the UI gives up and goes stale before
+  // the backend ever resolves. Poll for 14 minutes; anything still running
+  // past that is a genuine anomaly worth surfacing distinctly rather than
+  // silently going quiet.
+  const POLL_CEILING_MS = 14 * 60 * 1000
+
  // Poll the execution until it reaches a terminal state, so the operator sees
  // provisioning progress and the final outcome without leaving the chat.
  async function track(id: string) {
-    for (let i = 0; i < 150; i++) { // ~6min ceiling at 2.5s
+    const deadline = Date.now() + POLL_CEILING_MS
+    while (Date.now() < deadline) {
      const e = await getExecution(id)
      if (e) {
        exec.set(id, e)
@@ -45,8 +75,10 @@
      }
      await new Promise((r) => setTimeout(r, 2500))
    }
-    // Timed out waiting — leave whatever we last saw, mark running-stalled.
-    if (!TERMINAL.has(exec.get(id)?.status ?? '')) phase.set(id, 'running')
+    // Genuinely outlasted the backend's own hard timeout — this means
+    // something is wrong beyond a slow command (e.g. the API is down).
+    // Say so explicitly instead of freezing on "running" with no signal.
+    if (!TERMINAL.has(exec.get(id)?.status ?? '')) phase.set(id, 'stalled')
  }

  async function decide(approval: PendingApproval, decision: 'approve' | 'deny') {
@@ -125,23 +157,60 @@
      <XIcon class="size-4" /><span>Denied.</span>
    </div>
  {:else if p === 'running' || p === 'deciding'}
-    <div class="my-2 flex items-center gap-2 rounded-lg border border-warning/40 bg-warning/5 px-3 py-2 text-xs text-muted-foreground">
-      <LoaderCircleIcon class="size-4 shrink-0 animate-spin text-warning" />
-      <span>{p === 'deciding' ? 'Submitting approval…' : `Running on ${approval.target}… (this can take a minute)`}</span>
+    {@const secs = elapsedSeconds(e)}
+    <div class="my-2 flex flex-col gap-1 rounded-lg border border-warning/40 bg-warning/5 px-3 py-2 text-xs text-muted-foreground">
+      <div class="flex items-center gap-2">
+        <LoaderCircleIcon class="size-4 shrink-0 animate-spin text-warning" />
+        <span>
+          {#if p === 'deciding'}
+            Submitting approval…
+          {:else}
+            Running on {approval.target}{secs !== null ? ` — ${fmtDuration(secs)} elapsed` : '…'}
+          {/if}
+        </span>
+      </div>
+      {#if p === 'running' && approval.command}
+        <code class="ml-6 block truncate opacity-70">{approval.command}</code>
+      {/if}
+      {#if p === 'running'}
+        <span class="ml-6 opacity-60">
+          Execution <code>{approval.executionId.slice(0, 8)}</code> — long installs can take several minutes; this
+          will resolve on its own (capped at 10 min) or you can check the Operations page for live output.
+        </span>
+      {/if}
+    </div>
+  {:else if p === 'stalled'}
+    <div class="my-2 flex flex-col gap-1 rounded-lg border border-destructive/40 bg-destructive/5 px-3 py-2 text-xs text-destructive">
+      <div class="flex items-center gap-2">
+        <XIcon class="size-4 shrink-0" />
+        <span class="font-medium">No update from the server in over 14 minutes.</span>
+        <Button size="sm" variant="outline" class="ml-auto h-6 px-2 text-xs" onclick={() => { phase.delete(approval.executionId); void track(approval.executionId) }}>
+          Check again
+        </Button>
+      </div>
+      <span class="pl-6 opacity-90">
+        The command itself is capped at 10 minutes server-side, so this is unusual — the API may be unreachable.
+        Execution <code>{approval.executionId}</code>. Check the Operations page directly.
+      </span>
    </div>
  {:else if approval.destructive}
-    <div class="my-2 flex items-center gap-2 rounded-lg border border-destructive/50 bg-destructive/10 px-3 py-2">
-      <ShieldCheckIcon class="size-4 shrink-0 text-destructive" />
-      <span class="flex-1 text-xs text-destructive">
-        <strong>DESTRUCTIVE</strong> — {approval.action} on {approval.target}. Type
-        "I confirm" in chat, or use the button.
-      </span>
-      <Button size="sm" variant="destructive" class="h-7 px-2.5 text-xs" onclick={() => decide(approval, 'approve')}>
-        <CheckIcon class="size-3" /><span class="ml-1">Confirm</span>
-      </Button>
-      <Button size="sm" variant="outline" class="h-7 px-2.5 text-xs" onclick={() => decide(approval, 'deny')}>
-        <XIcon class="size-3" /><span class="ml-1">Deny</span>
-      </Button>
+    <div class="my-2 flex flex-col gap-1 rounded-lg border border-destructive/50 bg-destructive/10 px-3 py-2">
+      <div class="flex items-center gap-2">
+        <ShieldCheckIcon class="size-4 shrink-0 text-destructive" />
+        <span class="flex-1 text-xs text-destructive">
+          <strong>DESTRUCTIVE</strong> — {approval.action} on {approval.target}. Type
+          "I confirm" in chat, or use the button.
+        </span>
+        <Button size="sm" variant="destructive" class="h-7 px-2.5 text-xs" onclick={() => decide(approval, 'approve')}>
+          <CheckIcon class="size-3" /><span class="ml-1">Confirm</span>
+        </Button>
+        <Button size="sm" variant="outline" class="h-7 px-2.5 text-xs" onclick={() => decide(approval, 'deny')}>
+          <XIcon class="size-3" /><span class="ml-1">Deny</span>
+        </Button>
+      </div>
+      {#if approval.command}
+        <code class="ml-6 block truncate text-xs text-destructive/80">{approval.command}</code>
+      {/if}
    </div>
  {:else}
    <div class="my-2 flex items-center gap-2 rounded-lg border border-warning/40 bg-warning/5 px-3 py-2">
--- a/web/src/lib/stores/chat.ts
+++ b/web/src/lib/stores/chat.ts
@@ -7,6 +7,8 @@ export interface PendingApproval {
  action: string
  target: string
  destructive: boolean
+  command?: string
+  purpose?: string
 }

 export interface ChatMessage {
@@ -40,7 +42,9 @@ function extractApprovals(tools: ToolCallResult[]): PendingApproval[] {
        executionId: m[1],
        action: t.args?.action ?? t.args?.purpose ?? t.name ?? 'unknown',
        target: t.args?.target ?? 'unknown',
-        destructive: /\bDESTRUCTIVE\b/.test(text)
+        destructive: /\bDESTRUCTIVE\b/.test(text),
+        command: t.args?.command,
+        purpose: t.args?.purpose
      })
    }
  }