From 8a6ffdaca1aa7d0ff5c764f6d687ae92a7b606ef Mon Sep 17 00:00:00 2001 From: garrytan Date: Wed, 30 Sep 2026 06:14:47 +0000 Subject: [PATCH] W1: shared hook logging helper (hosts/claude/hooks/hook-log.ts) One hook-errors.log writer: root from resolveStateRoot, 0600 on every append, opt-in rate limit used only by memorable-user-prompt. The five hooks route through it. --- hosts/claude/hooks/auq-error-fallback-hook.ts | 21 +---- hosts/claude/hooks/hook-log.ts | 59 ++++++++++++++ .../hooks/memorable-user-prompt-hook.ts | 46 +++-------- hosts/claude/hooks/question-log-hook.ts | 16 +--- .../claude/hooks/question-preference-hook.ts | 22 +---- hosts/claude/hooks/timeline-stop-hook.ts | 19 +---- test/hook-log.test.ts | 81 +++++++++++++++++++ 7 files changed, 161 insertions(+), 103 deletions(-) create mode 100644 hosts/claude/hooks/hook-log.ts create mode 100644 test/hook-log.test.ts diff --git a/hosts/claude/hooks/auq-error-fallback-hook.ts b/hosts/claude/hooks/auq-error-fallback-hook.ts index 1f4eee820..d46ab87dd 100755 --- a/hosts/claude/hooks/auq-error-fallback-hook.ts +++ b/hosts/claude/hooks/auq-error-fallback-hook.ts @@ -30,9 +30,9 @@ */ import * as fs from 'fs'; import * as path from 'path'; -import * as os from 'os'; import { runBin } from './spawn-bin'; import { SPAWNED_ESCAPE_SENTENCE } from './spawned-directive'; +import { logHookError as sharedLogHookError } from './hook-log'; interface HookStdin { tool_name?: string; @@ -40,25 +40,8 @@ interface HookStdin { cwd?: string; } -function stateRoot(): string { - return ( - process.env.GSTACK_STATE_ROOT || - process.env.GSTACK_HOME || - path.join(os.homedir(), '.gstack') - ); -} - function logHookError(msg: string): void { - try { - const sr = stateRoot(); - fs.mkdirSync(sr, { recursive: true }); - fs.appendFileSync( - path.join(sr, 'hook-errors.log'), - `${new Date().toISOString()} auq-error-fallback-hook: ${msg}\n`, - ); - } catch { - // last-resort swallow - } + sharedLogHookError('auq-error-fallback-hook', msg); } function readStdin(): Promise { diff --git a/hosts/claude/hooks/hook-log.ts b/hosts/claude/hooks/hook-log.ts new file mode 100644 index 000000000..5baa81813 --- /dev/null +++ b/hosts/claude/hooks/hook-log.ts @@ -0,0 +1,59 @@ +/** + * hook-log — the one hook-errors.log writer for the Claude Code hooks in this + * directory. Root from resolveStateRoot() (lib/state-root.ts), mode 0600 on + * every append (an existing 0644 log is tightened), best-effort: logging never + * blocks a hook. Add a hook: `logHookError('my-hook', msg)`; pass + * `{ rateLimit: { nowMs, key } }` to drop repeats within LOG_RATE_LIMIT_MS + * (only memorable-user-prompt uses it). Moved from the five hooks' private + * copies; test/hook-log.test.ts pins the shared root and the mode. + */ +import * as fs from 'fs'; +import * as path from 'path'; +import { createHash } from 'crypto'; +import { resolveStateRoot } from '../../../lib/state-root'; + +export const LOG_RATE_LIMIT_MS = 10 * 60 * 1000; +/** Distinct rate-limit keys remembered at once (the marker file is rewritten on every log line). */ +const RATE_LIMIT_KEYS = 32; + +export interface HookLogOptions { + /** Drop a repeat of `key` logged by this hook within LOG_RATE_LIMIT_MS of `nowMs`. */ + rateLimit?: { nowMs: number; key: string }; +} + +export function hookErrorLogPath(env: NodeJS.ProcessEnv = process.env): string { + return path.join(resolveStateRoot(env), 'hook-errors.log'); +} + +/** + * Append one line to /hook-errors.log. With `rateLimit`, a + * per-hook marker (`hook-errors..last`, up to RATE_LIMIT_KEYS live + * `digest:ts` lines) suppresses repeats, so hooks never contend on it. + */ +export function logHookError(hook: string, msg: string, opts: HookLogOptions = {}): void { + try { + const root = resolveStateRoot(); + fs.mkdirSync(root, { recursive: true }); + const nowMs = opts.rateLimit?.nowMs ?? Date.now(); + if (opts.rateLimit) { + const marker = path.join(root, `hook-errors.${hook}.last`); + const digest = createHash('sha256').update(opts.rateLimit.key).digest('hex').slice(0, 16); + const live: string[] = []; + try { + for (const line of fs.readFileSync(marker, 'utf8').split('\n')) { + const [d, ts] = line.trim().split(':'); + if (!d || !ts || nowMs - Number(ts) >= LOG_RATE_LIMIT_MS) continue; + if (d === digest) return; + live.push(line.trim()); + } + } catch { /* no marker yet */ } + live.push(`${digest}:${nowMs}`); + fs.writeFileSync(marker, `${live.slice(-RATE_LIMIT_KEYS).join('\n')}\n`, { mode: 0o600 }); + } + const log = path.join(root, 'hook-errors.log'); + fs.appendFileSync(log, `${new Date(nowMs).toISOString()} ${hook}: ${msg}\n`, { mode: 0o600 }); + if (process.platform !== 'win32') { try { fs.chmodSync(log, 0o600); } catch { /* not ours to tighten */ } } + } catch { + // best-effort; never block the session because logging failed + } +} diff --git a/hosts/claude/hooks/memorable-user-prompt-hook.ts b/hosts/claude/hooks/memorable-user-prompt-hook.ts index 652006763..c5fb34b4c 100644 --- a/hosts/claude/hooks/memorable-user-prompt-hook.ts +++ b/hosts/claude/hooks/memorable-user-prompt-hook.ts @@ -58,6 +58,9 @@ import { import { wrapUntrustedTrackerContent } from '../../../lib/tracker-guard'; import { scan } from '../../../lib/redact-engine'; import { hasRepoPolicyStore, repoPolicyTier } from '../../../lib/gbrain-repo-policy-client'; +import { LOG_RATE_LIMIT_MS, logHookError as sharedLogHookError } from './hook-log'; + +export { LOG_RATE_LIMIT_MS }; export const BUDGET_MS = 4500; export const STDIN_CAP_BYTES = 1024 * 1024; @@ -74,7 +77,6 @@ export const RECHECK_CAP_MS = 500; export const OUTCOME_MIN_MS = 80; /** Kept back from the clock when an outcome append is given the rest of it. */ export const OUTCOME_RESERVE_MS = 50; -export const LOG_RATE_LIMIT_MS = 10 * 60 * 1000; export const ENVELOPE_SOURCE = 'memorable recall (third-party)'; export const SINK = 'memorable-recall'; export const CONSENT = 'memorable_recall=on'; @@ -84,8 +86,6 @@ export const PAYLOAD_CLASS = 'claude-user-prompt-json->local-vendor-cli'; const HOOK_NAME = 'memorable-user-prompt-hook'; /** Per-KiB allowance added to the scan admission check: ~1.5x the measured worst case of scan(). */ const SCAN_MS_PER_KIB = 1; -/** Distinct rate-limit keys remembered at once (the marker file is rewritten on every log line). */ -const RATE_LIMIT_KEYS = 32; /** Candidate objects tried by the tolerant stdout parser before giving up (bounds a hostile brace soup). */ const JSON_CANDIDATES = 64; const GIT_MAX_BUFFER = 64 * 1024; @@ -299,44 +299,16 @@ export function resolveVendor(env: Record, homeDir: return onPath && executable(onPath) ? onPath : null; } -function stateRoot(): string { - return process.env.GSTACK_STATE_ROOT || process.env.GSTACK_HOME || process.env.GSTACK_STATE_DIR - || path.join(os.homedir(), '.gstack'); -} - /** - * Best-effort, rate-limited: a message with the same `key` (default: the - * message itself) within LOG_RATE_LIMIT_MS is not re-logged, so a vendor that - * fails on every prompt with a different timestamp in its stderr still costs - * one line per ten minutes, and two alternating failures cost two. The marker - * (up to RATE_LIMIT_KEYS live `digest:ts` lines) is per hook so hooks never - * contend. The log is chmod 0600 on every append: sibling hooks create the - * same file without a mode, and it can name the session's cwd and vendor + * Best-effort, rate-limited (hook-log.ts): a message with the same `key` + * (default: the message itself) within LOG_RATE_LIMIT_MS is not re-logged, so + * a vendor that fails on every prompt with a different timestamp in its stderr + * still costs one line per ten minutes, and two alternating failures cost two. + * The log is 0600 on every append; it can name the session's cwd and vendor * diagnostics. */ export function logHookError(msg: string, nowMs: number = Date.now(), key: string = msg): void { - try { - const root = stateRoot(); - fs.mkdirSync(root, { recursive: true }); - const marker = path.join(root, `hook-errors.${HOOK_NAME}.last`); - const digest = sha256Hex(key).slice(0, 16); - const live: string[] = []; - try { - for (const line of fs.readFileSync(marker, 'utf8').split('\n')) { - const [d, ts] = line.trim().split(':'); - if (!d || !ts || nowMs - Number(ts) >= LOG_RATE_LIMIT_MS) continue; - if (d === digest) return; - live.push(line.trim()); - } - } catch { /* no marker yet */ } - live.push(`${digest}:${nowMs}`); - fs.writeFileSync(marker, `${live.slice(-RATE_LIMIT_KEYS).join('\n')}\n`, { mode: 0o600 }); - const log = path.join(root, 'hook-errors.log'); - fs.appendFileSync(log, `${new Date(nowMs).toISOString()} ${HOOK_NAME}: ${msg}\n`, { mode: 0o600 }); - if (process.platform !== 'win32') { try { fs.chmodSync(log, 0o600); } catch { /* not ours to tighten */ } } - } catch { - // best-effort; never block the session because logging failed - } + sharedLogHookError(HOOK_NAME, msg, { rateLimit: { nowMs, key } }); } function readStdin(maxBytes: number, timeoutMs: number): Promise<{ buf: Buffer; oversize: boolean; timedOut: boolean }> { diff --git a/hosts/claude/hooks/question-log-hook.ts b/hosts/claude/hooks/question-log-hook.ts index 62952a778..3d99c3d92 100644 --- a/hosts/claude/hooks/question-log-hook.ts +++ b/hosts/claude/hooks/question-log-hook.ts @@ -35,8 +35,8 @@ import * as crypto from 'crypto'; import * as fs from 'fs'; import * as path from 'path'; -import * as os from 'os'; import { runBin } from './spawn-bin'; +import { logHookError as sharedLogHookError } from './hook-log'; interface HookStdin { session_id?: string; @@ -69,19 +69,7 @@ const MARKER_RE = //i; const RECOMMENDED_LABEL_RE = /\(recommended\)\s*$/i; function logHookError(msg: string): void { - try { - const stateRoot = - process.env.GSTACK_STATE_ROOT || - process.env.GSTACK_HOME || - path.join(os.homedir(), '.gstack'); - fs.mkdirSync(stateRoot, { recursive: true }); - fs.appendFileSync( - path.join(stateRoot, 'hook-errors.log'), - `${new Date().toISOString()} question-log-hook: ${msg}\n`, - ); - } catch { - // Last-resort: swallow. Hook must not block. - } + sharedLogHookError('question-log-hook', msg); } function readStdin(): Promise { diff --git a/hosts/claude/hooks/question-preference-hook.ts b/hosts/claude/hooks/question-preference-hook.ts index 3e488363f..dd7e860a4 100644 --- a/hosts/claude/hooks/question-preference-hook.ts +++ b/hosts/claude/hooks/question-preference-hook.ts @@ -42,11 +42,12 @@ */ import * as fs from 'fs'; import * as path from 'path'; -import * as os from 'os'; import { runBin, repoRoot } from './spawn-bin'; import { isConductor } from '../../../lib/is-conductor'; import { classifyQuestion } from '../../../scripts/one-way-doors'; import { SPAWNED_ESCAPE_SENTENCE, CONDUCTOR_SPAWNED_DENY_REASON, spawnedByEnv } from './spawned-directive'; +import { resolveStateRoot } from '../../../lib/state-root'; +import { logHookError as sharedLogHookError } from './hook-log'; interface HookStdin { session_id?: string; @@ -66,25 +67,10 @@ interface HookStdin { const MARKER_RE = //i; const RECOMMENDED_LABEL_RE = /\(recommended\)\s*$/i; -function stateRoot(): string { - return ( - process.env.GSTACK_STATE_ROOT || - process.env.GSTACK_HOME || - path.join(os.homedir(), '.gstack') - ); -} +const stateRoot = (): string => resolveStateRoot(); function logHookError(msg: string): void { - try { - const sr = stateRoot(); - fs.mkdirSync(sr, { recursive: true }); - fs.appendFileSync( - path.join(sr, 'hook-errors.log'), - `${new Date().toISOString()} question-preference-hook: ${msg}\n`, - ); - } catch { - // last-resort swallow - } + sharedLogHookError('question-preference-hook', msg); } function readStdin(): Promise { diff --git a/hosts/claude/hooks/timeline-stop-hook.ts b/hosts/claude/hooks/timeline-stop-hook.ts index 30fca9f8b..f0e658e57 100755 --- a/hosts/claude/hooks/timeline-stop-hook.ts +++ b/hosts/claude/hooks/timeline-stop-hook.ts @@ -38,6 +38,8 @@ import * as fs from 'fs'; import * as os from 'os'; import * as path from 'path'; import { runBin } from './spawn-bin'; +import { resolveStateRoot } from '../../../lib/state-root'; +import { logHookError as sharedLogHookError } from './hook-log'; const DEADLINE_MS = 2000; const MAX_TIMELINE_BYTES = 10 * 1024 * 1024; @@ -68,21 +70,8 @@ function readTimelineTail(timelinePath: string, size: number): string { } } -function stateRoot(): string { - return process.env.GSTACK_HOME || path.join(os.homedir(), '.gstack'); -} - function logHookError(msg: string): void { - try { - const root = stateRoot(); - fs.mkdirSync(root, { recursive: true }); - fs.appendFileSync( - path.join(root, 'hook-errors.log'), - `${new Date().toISOString()} timeline-stop-hook: ${msg}\n`, - ); - } catch { - // best-effort; never block the session because logging failed - } + sharedLogHookError('timeline-stop-hook', msg); } interface TimelineEntry { @@ -120,7 +109,7 @@ function main(): void { return; } - const timelinePath = path.join(stateRoot(), 'projects', slug, 'timeline.jsonl'); + const timelinePath = path.join(resolveStateRoot(), 'projects', slug, 'timeline.jsonl'); let stat: fs.Stats; try { stat = fs.statSync(timelinePath); diff --git a/test/hook-log.test.ts b/test/hook-log.test.ts new file mode 100644 index 000000000..57c78ace8 --- /dev/null +++ b/test/hook-log.test.ts @@ -0,0 +1,81 @@ +/** + * hosts/claude/hooks/hook-log.ts is the one hook-errors.log writer. All five + * Claude Code hooks must log under the same resolved state root for the same + * env, and the log must end up 0600 even when it already existed as 0644. + */ +import { describe, test, expect } from 'bun:test'; +import { spawnSync } from 'child_process'; +import * as fs from 'fs'; +import * as os from 'os'; +import * as path from 'path'; + +const ROOT = path.resolve(import.meta.dir, '..'); +const HOOKS = path.join(ROOT, 'hosts', 'claude', 'hooks'); + +function runHook(name: string, stdin: string, env: Record, cwd: string) { + return spawnSync('bash', [path.join(HOOKS, name)], { + input: stdin, + cwd, + env: { ...process.env, GSTACK_STATE_ROOT: '', GSTACK_STATE_DIR: '', CLAUDE_PLUGIN_DATA: '', ...env }, + encoding: 'utf-8', + timeout: 30_000, + }); +} + +describe('hook-log: one root, one mode', () => { + test('all five hooks append to /hook-errors.log, and a 0644 log becomes 0600', () => { + const tmp = fs.mkdtempSync(path.join(os.tmpdir(), 'gstack-hook-log-')); + try { + const state = path.join(tmp, 'state'); + const home = path.join(tmp, 'home'); + const proj = path.join(tmp, 'hooklog-proj'); + fs.mkdirSync(state, { recursive: true }); + fs.mkdirSync(home, { recursive: true }); + fs.mkdirSync(proj, { recursive: true }); + const log = path.join(state, 'hook-errors.log'); + fs.writeFileSync(log, ''); + fs.chmodSync(log, 0o644); + const env = { GSTACK_HOME: state, HOME: home }; + + for (const hook of ['question-log-hook', 'question-preference-hook', 'auq-error-fallback-hook', 'memorable-user-prompt-hook']) { + const r = runHook(hook, '{not json', env, proj); + expect(r.status).toBe(0); + } + const slug = spawnSync('bash', [path.join(ROOT, 'bin', 'gstack-slug')], { cwd: proj, env: { ...process.env, ...env }, encoding: 'utf-8', timeout: 30_000 }) + .stdout.match(/^SLUG=(.+)$/m)?.[1]; + expect(slug).toBeTruthy(); + const timeline = path.join(state, 'projects', slug!, 'timeline.jsonl'); + fs.mkdirSync(path.dirname(timeline), { recursive: true }); + fs.writeFileSync(timeline, ''); + fs.truncateSync(timeline, 10 * 1024 * 1024 + 1); + expect(runHook('timeline-stop-hook', JSON.stringify({ cwd: proj }), env, proj).status).toBe(0); + + const text = fs.readFileSync(log, 'utf-8'); + for (const hook of ['question-log-hook', 'question-preference-hook', 'auq-error-fallback-hook', 'memorable-user-prompt-hook', 'timeline-stop-hook']) { + expect(text).toContain(` ${hook}: `); + } + expect(fs.existsSync(path.join(home, '.gstack', 'hook-errors.log'))).toBe(false); + if (process.platform !== 'win32') expect(fs.statSync(log).mode & 0o777).toBe(0o600); + } finally { + fs.rmSync(tmp, { recursive: true, force: true }); + } + }); + + test('rate limit drops a repeat key within the window and logs it again after', async () => { + const tmp = fs.mkdtempSync(path.join(os.tmpdir(), 'gstack-hook-log-rl-')); + const saved = process.env.GSTACK_HOME; + process.env.GSTACK_HOME = tmp; + try { + const { logHookError, LOG_RATE_LIMIT_MS } = await import('../hosts/claude/hooks/hook-log'); + logHookError('rl-hook', 'first', { rateLimit: { nowMs: 1_000, key: 'k' } }); + logHookError('rl-hook', 'second', { rateLimit: { nowMs: 2_000, key: 'k' } }); + logHookError('rl-hook', 'third', { rateLimit: { nowMs: 1_000 + LOG_RATE_LIMIT_MS, key: 'k' } }); + logHookError('rl-hook', 'plain'); + const lines = fs.readFileSync(path.join(tmp, 'hook-errors.log'), 'utf-8').trim().split('\n'); + expect(lines.map((l) => l.split(': ')[1])).toEqual(['first', 'third', 'plain']); + } finally { + if (saved === undefined) delete process.env.GSTACK_HOME; else process.env.GSTACK_HOME = saved; + fs.rmSync(tmp, { recursive: true, force: true }); + } + }); +});