screen #3948: merge 1ee952242b onto main b3e9e5d32c

changelog.d/gsta262-hook-budget.md

@@ -0,0 +1,3 @@
+### Fixed
+
+- **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.

hosts/claude/hooks/question-log-hook.ts

@@ -35,9 +35,11 @@
 import * as crypto from 'crypto';
 import * as fs from 'fs';
 import * as path from 'path';
-import { runBin } from './spawn-bin';
+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;
@@ -67,6 +69,15 @@ 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);
@@ -238,17 +249,19 @@ function detectSkill(cwd: string | undefined): string {
   return 'unknown';
 }
 
-function spawnLog(payload: Record<string, unknown>, cwd?: string): void {
+function spawnLog(payload: Record<string, unknown>, budgetMs: number, cwd?: string): void {
+  const startedAt = Date.now();
   const res = runBin('gstack-question-log', [JSON.stringify(payload)], {
     encoding: 'utf-8',
     stdio: ['ignore', 'pipe', 'pipe'],
-    timeout: 3000,
+    timeout: budgetMs,
     // Run from the originating tool call's cwd so gstack-slug resolves to
     // the project the user is actually in, not the hook script's location.
     cwd: cwd && fs.existsSync(cwd) ? cwd : undefined,
   });
   if (res.status !== 0) {
-    logHookError(`gstack-question-log exited ${res.status}: ${res.stderr || res.stdout}`);
+    const how = res.signal ? ` (${res.signal} after ${Date.now() - startedAt} of ${budgetMs} ms)` : '';
+    logHookError(`gstack-question-log exited ${res.status}${how}: ${res.stderr || res.stdout}`);
   }
 }
 
@@ -283,6 +296,7 @@ async function main(): Promise<void> {
   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];
@@ -309,13 +323,21 @@ async function main(): Promise<void> {
     if (signal_key) payload.signal_key = signal_key;
     if (choice.free_text) payload.free_text = String(choice.free_text);
 
-    spawnLog(payload, stdin.cwd);
+    const budgetMs = hookChildBudgetMs(HOOK_STARTED_AT);
+    const skip = launchSkipReason(budgetMs);
+    if (skip) {
+      logHookError(`gstack-question-log skipped for questions ${i + 1}-${questions.length}: ${skip}`);
+      break;
+    }
+    spawnLog(payload, budgetMs, stdin.cwd);
   }
 
   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);
+  });
+}

hosts/claude/hooks/spawn-bin.ts

@@ -41,6 +41,21 @@ export function runBin(name: string, args: string[], opts: SpawnSyncOptions) {
   });
 }
 
+/** Claude Code's timeout for a gstack hook, as setup registers it (`--timeout 5`). */
+export const HOOK_TIMEOUT_MS = 5000;
+/** Kept back from HOOK_TIMEOUT_MS so a hook logs and exits before Claude Code kills it. */
+const HOOK_EXIT_RESERVE_MS = 500;
+
+/**
+ * What is left of a hook's registered budget for its next child. Every child
+ * a hook spawns shares one deadline: a fixed per-child timeout either kills a
+ * cold child that would have finished in time, or lets several children run
+ * past the point where Claude Code kills the hook itself.
+ */
+export function hookChildBudgetMs(startedAtMs: number, nowMs: number = Date.now()): number {
+  return HOOK_TIMEOUT_MS - HOOK_EXIT_RESERVE_MS - (nowMs - startedAtMs);
+}
+
 /** Kept tail of the child's stderr, for the caller's error log. */
 const STDERR_TAIL_BYTES = 500;
 /** After a group kill, how long to wait for 'exit'/'close' before resolving anyway (kept under the callers' post-spawn reserve). */

test/question-log-hook.test.ts

@@ -19,6 +19,8 @@ import * as fs from 'fs';
 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');
@@ -394,3 +396,59 @@ describe('PostToolUse hook (crash safety)', () => {
     expect(fs.readFileSync(errLog, 'utf-8')).toContain('stdin parse failed');
   });
 });
+
+// ----------------------------------------------------------------------
+// One budget for every child (Claude Code kills the hook at 5 s)
+// ----------------------------------------------------------------------
+
+describe('PostToolUse hook (budget)', () => {
+  test('every child shares the registered 5 s budget, less the exit reserve', () => {
+    expect(hookChildBudgetMs(1_000, 1_000)).toBe(4_500);
+    expect(hookChildBudgetMs(1_000, 3_000)).toBe(2_500);
+    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 5\nexec "${process.execPath}" "$@"\n`, { mode: 0o755 });
+      const env: Record<string, string> = {};
+      for (const [k, v] of Object.entries(process.env)) {
+        if (v !== undefined) env[k] = v;
+      }
+      env.GSTACK_STATE_ROOT = stateRoot;
+      delete env.GSTACK_HOME;
+      env.GSTACK_QUESTION_LOG_NO_DERIVE = '1';
+      env.PATH = `${fakeBin}${path.delimiter}${env.PATH ?? ''}`;
+      const questions = Array.from({ length: 6 }, (_, i) => ({ question: `Budget question ${i}`, options: ['A', 'B'] }));
+      const res = spawnSync(process.execPath, [path.join(ROOT, 'hosts', 'claude', 'hooks', 'question-log-hook.ts')], {
+        env,
+        input: JSON.stringify({
+          session_id: 'budget',
+          tool_name: 'AskUserQuestion',
+          tool_use_id: 'tu-budget',
+          tool_input: { questions },
+          tool_response: { answers: questions.map(() => ({ option_label: 'A' })) },
+          cwd: ROOT,
+        }),
+        encoding: 'utf-8',
+        cwd: ROOT,
+        timeout: 30_000,
+      });
+      expect(res.status).toBe(0);
+      expect(readLog().length).toBeLessThan(questions.length);
+      const errors = fs.readFileSync(path.join(stateRoot, 'hook-errors.log'), 'utf-8');
+      expect(errors).toMatch(/exited null \(SIG\w+ after \d+ of \d+ ms\)/);
+      expect(errors).toContain('budget is spent');
+    } finally {
+      fs.rmSync(fakeBin, { recursive: true, force: true });
+    }
+  }, 30_000);
+});