diff --git a/src/main/git/command-runner/exec-file-capture.ts b/src/main/git/command-runner/exec-file-capture.ts index e9ae815ff34..f343246571d 100644 --- a/src/main/git/command-runner/exec-file-capture.ts +++ b/src/main/git/command-runner/exec-file-capture.ts @@ -15,6 +15,8 @@ type ExecFileCaptureOptions = Omit & { 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( diff --git a/src/main/git/command-runner/gh-exec-file.ts b/src/main/git/command-runner/gh-exec-file.ts index e8308a8e4b4..9a92f1d59de 100644 --- a/src/main/git/command-runner/gh-exec-file.ts +++ b/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 ) diff --git a/src/main/git/command-runner/glab-exec-file.ts b/src/main/git/command-runner/glab-exec-file.ts index 3257dd9e818..37aad697b95 100644 --- a/src/main/git/command-runner/glab-exec-file.ts +++ b/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 ) diff --git a/src/main/git/command-runner/hosted-cli-deadline-log.test.ts b/src/main/git/command-runner/hosted-cli-deadline-log.test.ts new file mode 100644 index 00000000000..06ad0e6261f --- /dev/null +++ b/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 + 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 + + 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) + }) +}) diff --git a/src/main/git/command-runner/hosted-cli-deadline-log.ts b/src/main/git/command-runner/hosted-cli-deadline-log.ts new file mode 100644 index 00000000000..3a8be660d14 --- /dev/null +++ b/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.` + ) +}