fix(hooks): question-log hook children share the hook's 5 s budget instead of a fixed 3 s each

Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com>

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 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.

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

@@ -35,7 +35,7 @@
 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';
 
@@ -67,6 +67,7 @@ interface ExtractedQuestion {
 }
 
 const RECOMMENDED_LABEL_RE = /\(recommended\)\s*$/i;
+const HOOK_STARTED_AT = Date.now() - Math.round(process.uptime() * 1000);
 
 function logHookError(msg: string): void {
   sharedLogHookError('question-log-hook', msg);
@@ -238,17 +239,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}`);
   }
 }
 
@@ -309,7 +312,12 @@ 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);
+    if (budgetMs <= 0) {
+      logHookError(`gstack-question-log skipped for questions ${i + 1}-${questions.length}: the hook's ${HOOK_TIMEOUT_MS} ms budget is spent`);
+      break;
+    }
+    spawnLog(payload, budgetMs, stdin.cwd);
   }
 
   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. */
+export 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,7 @@ import * as fs from 'fs';
 import * as path from 'path';
 import * as os from 'os';
 import { spawnSync } from 'child_process';
+import { HOOK_EXIT_RESERVE_MS, HOOK_TIMEOUT_MS, hookChildBudgetMs } from '../hosts/claude/hooks/spawn-bin';
 
 const ROOT = path.resolve(import.meta.dir, '..');
 const HOOK = path.join(ROOT, 'hosts', 'claude', 'hooks', 'question-log-hook');
@@ -394,3 +395,50 @@ 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(HOOK_TIMEOUT_MS - HOOK_EXIT_RESERVE_MS);
+    expect(hookChildBudgetMs(1_000, 3_000)).toBe(HOOK_TIMEOUT_MS - HOOK_EXIT_RESERVE_MS - 2_000);
+    expect(hookChildBudgetMs(1_000, 1_000 + HOOK_TIMEOUT_MS)).toBeLessThan(0);
+  });
+
+  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 });
+      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);
+      expect(fs.readFileSync(path.join(stateRoot, 'hook-errors.log'), 'utf-8')).toContain('budget is spent');
+    } finally {
+      fs.rmSync(fakeBin, { recursive: true, force: true });
+    }
+  }, 30_000);
+});