fix(gh): log when gh/glab is killed at its deadline (#18555)

src/main/git/command-runner/exec-file-capture.ts

@@ -15,6 +15,8 @@ type ExecFileCaptureOptions = Omit<ExecFileOptions, 'timeout'> & {
   onChildTerminated?: () => void
   admissionTier?: GitAdmissionTier
   createTimeoutError?: () => Error
+  /** Called once when the deadline — not an abort — is what ended the process. */
+  onDeadlineKill?: () => void
 }
 
 const GIT_TERMINATION_BARRIER_FALLBACK_TIMEOUT_MS = 2_147_000_000
@@ -54,6 +56,9 @@ export async function execFileCaptureToTermination(
   ) {
     return { stdout, stderr }
   }
+  if (result.timedOut && !options.signal?.aborted) {
+    options.onDeadlineKill?.()
+  }
   const error = result.timedOut
     ? (options.createTimeoutError?.() ?? new Error(`${command} timed out.`))
     : new Error(

src/main/git/command-runner/gh-exec-file.ts

@@ -20,6 +20,7 @@ import {
   resolveHostGitHubCli
 } from './github-cli-host-fallback'
 import { execFileCaptureToTermination } from './exec-file-capture'
+import { logHostedCliDeadlineKill } from './hosted-cli-deadline-log'
 import type { GitExecOptions } from './git-exec-options'
 import { argsLookIdempotent } from './gh-idempotency'
 import { applyGhHostToArgs, explicitGhHostname, explicitGhRepoHostname } from './gh-host-args'
@@ -109,6 +110,7 @@ export async function ghExecFileAsync(
   // Why: scope by runtime and host so unrelated github.com, GHES, and WSL quotas cannot block each other.
   const rateLimitBucket = classifyGhRateLimitBucket(args)
   const rateLimitProbe = isGhRateLimitProbe(args)
+  const timeoutMs = options.timeout ?? defaultGhExecTimeoutMs(options.env)
   assertGhRateLimitScopeAvailable(args, options, resolved, rateLimitBucket, rateLimitProbe)
   let lastError: unknown
   let attemptedHostFallback = false
@@ -128,9 +130,10 @@ export async function ghExecFileAsync(
           encoding: (options.encoding ?? 'utf-8') as BufferEncoding,
           maxBuffer: options.maxBuffer,
           // Why: bound gh so one stuck child fails visibly instead of wedging the IPC lane.
-          timeout: options.timeout ?? defaultGhExecTimeoutMs(options.env),
+          timeout: timeoutMs,
           env: nonInteractiveGhEnv(options.env),
-          signal: options.signal
+          signal: options.signal,
+          onDeadlineKill: () => logHostedCliDeadlineKill('gh', resolved.binary, args, timeoutMs)
         },
         resolved.termination
       )

src/main/git/command-runner/glab-exec-file.ts

@@ -3,6 +3,7 @@ import { extractExecError, parseRetryAfterMs } from '../exec-error'
 import { resolveCommand, resolveDefaultWslCli } from './wsl-command-resolution'
 import { isHostCommandMissing } from './github-cli-host-fallback'
 import { execFileCaptureToTermination } from './exec-file-capture'
+import { logHostedCliDeadlineKill } from './hosted-cli-deadline-log'
 import type { GitExecOptions } from './git-exec-options'
 import { argsLookIdempotent } from './gh-idempotency'
 import {
@@ -59,6 +60,7 @@ export async function glabExecFileAsync(
 ): Promise<{ stdout: string; stderr: string }> {
   ;({ args, options } = redirectPortedHostnameToEnv(args, options))
   let resolved = resolveCommand('glab', args, options.cwd, options.wslDistro)
+  const timeoutMs = options.timeout ?? DEFAULT_GLAB_EXEC_TIMEOUT_MS
   let lastError: unknown
   let attemptedDefaultWslFallback = false
   for (let attempt = 0; attempt <= GH_RETRY_DELAYS_MS.length; attempt++) {
@@ -72,9 +74,10 @@ export async function glabExecFileAsync(
           cwd: resolved.cwd,
           encoding: (options.encoding ?? 'utf-8') as BufferEncoding,
           maxBuffer: options.maxBuffer,
-          timeout: options.timeout ?? DEFAULT_GLAB_EXEC_TIMEOUT_MS,
+          timeout: timeoutMs,
           env: options.env,
-          signal: options.signal
+          signal: options.signal,
+          onDeadlineKill: () => logHostedCliDeadlineKill('glab', resolved.binary, args, timeoutMs)
         },
         resolved.termination
       )

src/main/git/command-runner/hosted-cli-deadline-log.test.ts

@@ -0,0 +1,94 @@
+import { EventEmitter } from 'node:events'
+import type { ChildProcess } from 'node:child_process'
+import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'
+
+const { spawnMock } = vi.hoisted(() => ({ spawnMock: vi.fn() }))
+
+vi.mock('node:child_process', async (importOriginal) => ({
+  ...(await importOriginal()),
+  spawn: spawnMock
+}))
+
+import { ghExecFileAsync } from './gh-exec-file'
+import { logHostedCliDeadlineKill } from './hosted-cli-deadline-log'
+
+function mockChild(pid = 4321): ChildProcess {
+  const child = new EventEmitter() as EventEmitter & Record<string, unknown>
+  child.pid = pid
+  child.kill = vi.fn(() => true)
+  child.stdin = Object.assign(new EventEmitter(), { end: vi.fn() })
+  child.stdout = new EventEmitter()
+  child.stderr = new EventEmitter()
+  return child as unknown as ChildProcess
+}
+
+/**
+ * #18234 took four rounds of strace/perf/proc spelunking from the reporter
+ * because a deadline kill produced no evidence at all. The resolved path is the
+ * fact that names a self-recursive wrapper.
+ */
+describe('hosted CLI deadline logging', () => {
+  let warn: ReturnType<typeof vi.spyOn>
+
+  beforeEach(() => {
+    vi.useFakeTimers()
+    spawnMock.mockReset()
+    warn = vi.spyOn(console, 'warn').mockImplementation(() => {})
+    vi.spyOn(process, 'kill').mockImplementation((() => true) as unknown as typeof process.kill)
+  })
+
+  afterEach(() => {
+    vi.useRealTimers()
+    vi.restoreAllMocks()
+  })
+
+  it('names the CLI, the deadline and the resolved path, and never the argv values', () => {
+    logHostedCliDeadlineKill(
+      'gh',
+      '/home/user/.local/bin/gh',
+      ['api', '-H', 'Authorization: token ghp_secret'],
+      15_000
+    )
+
+    const line = warn.mock.calls[0][0] as string
+    expect(line).toContain('[gh]')
+    expect(line).toContain('15000ms')
+    expect(line).toContain('/home/user/.local/bin/gh')
+    expect(line).toContain('"api"')
+    expect(line).toContain('(3 args)')
+    expect(line).not.toContain('ghp_secret')
+    expect(line).not.toContain('Authorization')
+  })
+
+  it('logs once when gh is killed at its deadline', async () => {
+    spawnMock.mockReturnValue(mockChild())
+
+    const rejection = expect(
+      ghExecFileAsync(['api', '--include', 'user/starred/stablyai/orca'], { timeout: 15_000 })
+    ).rejects.toThrow('timed out')
+    await vi.advanceTimersByTimeAsync(15_000)
+    await vi.advanceTimersByTimeAsync(15_000)
+    await rejection
+
+    const deadlineLines = warn.mock.calls.filter((call) => String(call[0]).startsWith('[gh]'))
+    expect(deadlineLines).toHaveLength(1)
+    expect(String(deadlineLines[0][0])).toContain('wrapper script')
+  })
+
+  it('stays quiet when the caller aborted rather than the deadline firing', async () => {
+    const controller = new AbortController()
+    spawnMock.mockReturnValue(mockChild())
+
+    const rejection = expect(
+      ghExecFileAsync(['api', '--include', 'user/starred/stablyai/orca'], {
+        timeout: 15_000,
+        signal: controller.signal
+      })
+    ).rejects.toThrow()
+    controller.abort()
+    await vi.advanceTimersByTimeAsync(15_000)
+    await rejection
+
+    expect(warn.mock.calls.filter((call) => String(call[0]).startsWith('[gh]'))).toHaveLength(0)
+  })
+})

src/main/git/command-runner/hosted-cli-deadline-log.ts

@@ -0,0 +1,26 @@
+/**
+ * One log line when `gh`/`glab` is killed at its deadline without answering.
+ *
+ * Why this exists: the deadline kill was completely silent. In #18234 a user's
+ * `~/.local/bin/gh` wrapper (`exec mise x gh -- gh "$@"`) re-execed itself in
+ * place at 100% CPU on every invocation, and the only evidence Orca produced was
+ * that GitHub features quietly did nothing. Diagnosing it took the reporter four
+ * rounds of `strace`, `perf` and `/proc` spelunking. The resolved path below is
+ * the single most useful fact — it names the wrapper.
+ *
+ * Why not the full argv: `gh api` carries `-H Authorization: …` and `--field`
+ * bodies, so only the subcommand and an argument count are safe to print.
+ */
+export function logHostedCliDeadlineKill(
+  cli: string,
+  resolvedBinary: string,
+  args: readonly string[],
+  timeoutMs: number
+): void {
+  const subcommand = args[0] ?? '(none)'
+  console.warn(
+    `[${cli}] killed at its ${timeoutMs}ms deadline without answering — ` +
+      `subcommand "${subcommand}" (${args.length} args), resolved to "${resolvedBinary}". ` +
+      `If that path is a wrapper script, check that it resolves the real ${cli} binary rather than itself.`
+  )
+}