diff --git a/changelog.d/gsta262-hook-budget.md b/changelog.d/gsta262-hook-budget.md index 9a0a8afdd..5435ae3a0 100644 --- a/changelog.d/gsta262-hook-budget.md +++ b/changelog.d/gsta262-hook-budget.md @@ -1,3 +1,3 @@ ### Fixed -- **The AskUserQuestion log hook no longer kills a slow first run on Windows, and never outlives Claude Code's 5-second hook limit.** `question-log-hook` gave each `gstack-question-log` call a fixed 3-second timeout. On a cold Windows runner the first call takes just over 3 seconds (3,149 and 3,188 ms in windows-pregate runs 41605458462 and 41406459043), so the hook killed it and logged "exited null" even though Claude Code allows the hook 5 seconds. A fixed timeout per call also let several questions run well past those 5 seconds (six slow calls took 16 s). Now every call gets what is left of the hook's 5-second budget, less a 500 ms exit reserve. When the budget runs out, the hook stops and logs which questions it skipped, and a killed call's log line names the signal and how long it ran. +- **The AskUserQuestion log hook no longer kills a slow first run on Windows, and its calls now share Claude Code's 5-second hook limit.** `question-log-hook` gave each `gstack-question-log` call a fixed 3-second timeout. On a cold Windows runner the first call takes just over 3 seconds (3,149 and 3,188 ms in windows-pregate runs 41605458462 and 41406459043), so the hook killed it and logged "exited null" even though Claude Code allows the hook 5 seconds. A fixed timeout per call also let several questions run well past those 5 seconds (six slow calls took 16 s). Now the calls share one budget: 5 seconds from when Bun starts the hook, less a 500 ms exit reserve. On Windows the hook finds Git Bash before it reads that budget, so the lookup comes out of the budget instead of adding to a call's time. When less than 250 ms is left, the hook skips the remaining questions and logs which ones; a killed call's log line names the signal and how long it ran. The budget doesn't cover the bash shim that starts Bun, and the first Git Bash lookup on a fresh install has no time limit of its own, so Claude Code can still stop the hook in those cases. diff --git a/hosts/claude/hooks/question-log-hook.ts b/hosts/claude/hooks/question-log-hook.ts index dec7b7e6f..f31417830 100644 --- a/hosts/claude/hooks/question-log-hook.ts +++ b/hosts/claude/hooks/question-log-hook.ts @@ -38,6 +38,8 @@ import * as path from 'path'; import { HOOK_TIMEOUT_MS, hookChildBudgetMs, runBin } from './spawn-bin'; import { logHookError as sharedLogHookError } from './hook-log'; import { parseQidMarker } from '../../../scripts/qid-marker'; +import { resolveWindowsBashCached } from '../../../lib/script-invocation'; +import { resolveStateRoot } from '../../../lib/state-root'; interface HookStdin { session_id?: string; @@ -68,6 +70,14 @@ interface ExtractedQuestion { const RECOMMENDED_LABEL_RE = /\(recommended\)\s*$/i; const HOOK_STARTED_AT = Date.now() - Math.round(process.uptime() * 1000); +/** Below this much budget a child cannot launch and finish, so the hook skips it instead of starting a call it must kill. */ +const MIN_LAUNCH_BUDGET_MS = 250; + +/** Why the next gstack-question-log call is skipped with `budgetMs` left, or null when it may launch. */ +export function launchSkipReason(budgetMs: number): string | null { + if (budgetMs >= MIN_LAUNCH_BUDGET_MS) return null; + return `the hook's ${HOOK_TIMEOUT_MS} ms budget is spent (${Math.max(0, budgetMs)} ms left, under the ${MIN_LAUNCH_BUDGET_MS} ms a call needs)`; +} function logHookError(msg: string): void { sharedLogHookError('question-log-hook', msg); @@ -286,6 +296,7 @@ async function main(): Promise { const choices = extractUserChoices(stdin.tool_response, questions, (msg) => logHookError(`${msg} (tool_use_id=${stdin.tool_use_id || 'n/a'})`), ); + if (process.platform === 'win32') resolveWindowsBashCached(path.join(resolveStateRoot(), 'cache', 'windows-bash.json')); for (let i = 0; i < questions.length; i++) { const q = questions[i]; @@ -313,8 +324,9 @@ async function main(): Promise { if (choice.free_text) payload.free_text = String(choice.free_text); const budgetMs = hookChildBudgetMs(HOOK_STARTED_AT); - if (budgetMs <= 0) { - logHookError(`gstack-question-log skipped for questions ${i + 1}-${questions.length}: the hook's ${HOOK_TIMEOUT_MS} ms budget is spent`); + const skip = launchSkipReason(budgetMs); + if (skip) { + logHookError(`gstack-question-log skipped for questions ${i + 1}-${questions.length}: ${skip}`); break; } spawnLog(payload, budgetMs, stdin.cwd); @@ -323,7 +335,9 @@ async function main(): Promise { process.exit(0); } -main().catch((e) => { - logHookError(`main crash: ${(e as Error).message}`); - process.exit(0); -}); +if (import.meta.main) { + main().catch((e) => { + logHookError(`main crash: ${(e as Error).message}`); + process.exit(0); + }); +} diff --git a/test/question-log-hook.test.ts b/test/question-log-hook.test.ts index 60f8b1896..1c06bcd31 100644 --- a/test/question-log-hook.test.ts +++ b/test/question-log-hook.test.ts @@ -20,6 +20,7 @@ import * as path from 'path'; import * as os from 'os'; import { spawnSync } from 'child_process'; import { hookChildBudgetMs } from '../hosts/claude/hooks/spawn-bin'; +import { launchSkipReason } from '../hosts/claude/hooks/question-log-hook.ts'; const ROOT = path.resolve(import.meta.dir, '..'); const HOOK = path.join(ROOT, 'hosts', 'claude', 'hooks', 'question-log-hook'); @@ -407,10 +408,17 @@ describe('PostToolUse hook (budget)', () => { expect(hookChildBudgetMs(1_000, 6_000)).toBeLessThan(0); }); + test('a call launches only with at least 250 ms of budget left', () => { + expect(launchSkipReason(4_500)).toBeNull(); + expect(launchSkipReason(250)).toBeNull(); + expect(launchSkipReason(249)).toBe("the hook's 5000 ms budget is spent (249 ms left, under the 250 ms a call needs)"); + expect(launchSkipReason(-40)).toBe("the hook's 5000 ms budget is spent (0 ms left, under the 250 ms a call needs)"); + }); + test('slow children stop at the hook budget and the skipped questions are logged', () => { const fakeBin = fs.mkdtempSync(path.join(os.tmpdir(), 'gstack-slow-bun-')); try { - fs.writeFileSync(path.join(fakeBin, 'bun'), `#!/bin/sh\nsleep 1\nexec "${process.execPath}" "$@"\n`, { mode: 0o755 }); + fs.writeFileSync(path.join(fakeBin, 'bun'), `#!/bin/sh\nsleep 5\nexec "${process.execPath}" "$@"\n`, { mode: 0o755 }); const env: Record = {}; for (const [k, v] of Object.entries(process.env)) { if (v !== undefined) env[k] = v;