From 6655b0afd4c332d20a28f99ad6f7aeaa41c0183e Mon Sep 17 00:00:00 2001 From: Taylor Mullen Date: Tue, 10 Feb 2026 16:37:18 -0800 Subject: [PATCH] repro: use simple echo hook and re-enable rich logging --- integration-tests/hooks-system.test.ts | 43 ++++++++++----------- packages/core/src/core/coreToolScheduler.ts | 4 ++ packages/core/src/hooks/hookRegistry.ts | 10 +++++ packages/core/src/hooks/hookRunner.ts | 18 +++++++++ packages/test-utils/src/test-rig.ts | 24 ++++++++++++ 5 files changed, 77 insertions(+), 22 deletions(-) diff --git a/integration-tests/hooks-system.test.ts b/integration-tests/hooks-system.test.ts index 88c7f954b2..aab1d6ac00 100644 --- a/integration-tests/hooks-system.test.ts +++ b/integration-tests/hooks-system.test.ts @@ -85,7 +85,7 @@ describe('Hooks System Integration', () => { expect(hookTelemetryFound).toBeTruthy(); }); - it('should block tool execution and use stderr as reason when hook exits with code 2', async () => { + it.only('should block tool execution and use stderr as reason when hook exits with code 2', async () => { rig.setup( 'should block tool execution and use stderr as reason when hook exits with code 2', { @@ -96,25 +96,25 @@ describe('Hooks System Integration', () => { }, ); - const scriptPath = rig.createScript( - 'stderr_block_hook.cjs', - ` -console.log(JSON.stringify({ - decision: 'deny', - reason: 'File writing blocked by security policy' -})); -process.exit(0); -`, - ); + const blockMsg = 'File writing blocked by security policy'; + const blockJson = JSON.stringify({ + decision: 'deny', + reason: blockMsg, + }); - const normalizedCmd = normalizePath(`node "${scriptPath}"`); + // Use a direct echo command to avoid Node.js startup flakiness/pathing + // On Windows PowerShell, we need to escape quotes carefully for echo + const echoCmd = + process.platform === 'win32' + ? `powershell -NoProfile -Command "echo '${blockJson.replace(/"/g, '\"')}'"` + : `echo '${blockJson}'`; rig.setup( 'should block tool execution and use stderr as reason when hook exits with code 2', { settings: { - enableHooks: true, - hooks: { + enableHooks: true, + hooks: { BeforeTool: [ { matcher: 'write_file', @@ -122,8 +122,7 @@ process.exit(0); hooks: [ { type: 'command', - // Exit with code 2 and write reason to stderr - command: normalizedCmd!, + command: echoCmd, timeout: 5000, }, ], @@ -148,19 +147,19 @@ process.exit(0); // Tool should not be called due to blocking hook expect(writeFileCalls).toHaveLength(0); - // Result should mention the blocking reason from stderr - expect(result).toContain('File writing blocked by security policy'); + // Result should mention the blocking reason + expect(result).toContain(blockMsg); // Verify hook telemetry shows the deny decision const hookLogs = rig.readHookLogs(); const blockHook = hookLogs.find( (log) => - log.hookCall.hook_name.includes('stderr_block_hook.cjs') && - log.hookCall.hook_output.includes('"decision":"deny"'), + log.hookCall.hook_event_name === 'BeforeTool' && + JSON.stringify(log.hookCall.hook_output).includes('"decision":"deny"'), ); expect(blockHook).toBeDefined(); - expect(blockHook?.hookCall.hook_output).toContain( - 'File writing blocked by security policy', + expect(JSON.stringify(blockHook?.hookCall.hook_output)).toContain( + blockMsg, ); }); diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index ec566da0fe..3ea97c8adf 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -966,6 +966,10 @@ export class CoreToolScheduler { // The active tool is finished. Move it to the completed batch. const completedCall = activeCall as CompletedToolCall; + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[CoreToolScheduler] Completed tool call: ${completedCall.request.name}, status: ${completedCall.status}`); + } + this.completedToolCallsForBatch.push(completedCall); logToolCall(this.config, new ToolCallEvent(completedCall)); diff --git a/packages/core/src/hooks/hookRegistry.ts b/packages/core/src/hooks/hookRegistry.ts index 1e5515a6a0..e90c60f4b5 100644 --- a/packages/core/src/hooks/hookRegistry.ts +++ b/packages/core/src/hooks/hookRegistry.ts @@ -233,6 +233,16 @@ please review the project settings (.gemini/settings.json) and remove them.`; } as HookRegistryEntry); const isDisabled = disabledHooks.includes(hookName); + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[HookRegistry] Processing hook: "${hookName}"`); + if (isDisabled) { + console.log(`[HookRegistry] Hook is DISABLED (found in disabledHooks list)`); + } + if (disabledHooks.length > 0) { + console.log(`[HookRegistry] Current disabledHooks: ${JSON.stringify(disabledHooks)}`); + } + } + // Add source to hook config hookConfig.source = source; diff --git a/packages/core/src/hooks/hookRunner.ts b/packages/core/src/hooks/hookRunner.ts index 6619bc51df..d7238d98be 100644 --- a/packages/core/src/hooks/hookRunner.ts +++ b/packages/core/src/hooks/hookRunner.ts @@ -268,6 +268,12 @@ export class HookRunner { shellConfig.shell, ); + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[HookRunner] shellConfig: ${JSON.stringify(shellConfig)}`); + console.log(`[HookRunner] command: ${command}`); + console.log(`[HookRunner] cwd: ${input.cwd}`); + } + // Set up environment variables const env = { ...sanitizeEnvironment(process.env, this.config.sanitizationConfig), @@ -333,6 +339,9 @@ export class HookRunner { }); child.on('exit', (code, signal) => { + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[HookRunner] Hook exit. code: ${code}, signal: ${signal}`); + } }); // Handle process exit @@ -340,6 +349,12 @@ export class HookRunner { clearTimeout(timeoutHandle); const duration = Date.now() - startTime; + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[HookRunner] Hook closed. exitCode: ${exitCode}, duration: ${duration}ms`); + console.log(`[HookRunner] stdout: ${stdout}`); + console.log(`[HookRunner] stderr: ${stderr}`); + } + if (timedOut) { resolve({ hookConfig, @@ -431,6 +446,9 @@ export class HookRunner { text: string, exitCode: number, ): HookOutput { + if (process.env['CI'] === 'true' || process.env['VERBOSE'] === 'true') { + console.log(`[HookRunner] convertPlainTextToHookOutput: exitCode=${exitCode}, text="${text}"`); + } if (exitCode === EXIT_CODE_SUCCESS) { // Success - treat as system message or additional context return { diff --git a/packages/test-utils/src/test-rig.ts b/packages/test-utils/src/test-rig.ts index 87983ba0e3..5caeccdcda 100644 --- a/packages/test-utils/src/test-rig.ts +++ b/packages/test-utils/src/test-rig.ts @@ -361,10 +361,19 @@ export class TestRig { this.testDir = join(testFileDir, sanitizedName); this.homeDir = join(testFileDir, sanitizedName + '-home'); + if (env['VERBOSE'] === 'true' || env['CI'] === 'true') { + console.log(`[TestRig] Setting up test: ${this.testName}`); + console.log(`[TestRig] testDir: ${this.testDir}`); + console.log(`[TestRig] homeDir: ${this.homeDir}`); + } + if (!this._initialized) { // Clean up existing directories from previous runs (e.g. retries) const cleanDir = (dir: string) => { if (fs.existsSync(dir)) { + if (env['VERBOSE'] === 'true' || env['CI'] === 'true') { + console.log(`[TestRig] Cleaning up existing directory: ${dir}`); + } for (let i = 0; i < 5; i++) { try { fs.rmSync(dir, { recursive: true, force: true }); @@ -762,6 +771,11 @@ export class TestRig { }); this._spawnedProcesses.push(child); + if (env['VERBOSE'] === 'true' || env['CI'] === 'true') { + console.log(`[TestRig] Running: ${command} ${commandArgs.join(' ')}`); + console.log(`[TestRig] CWD: ${this.testDir}`); + } + let stdout = ''; let stderr = ''; @@ -1245,6 +1259,11 @@ export class TestRig { }[] = []; for (const logData of parsedLogs) { + if (env['VERBOSE'] === 'true' || env['CI'] === 'true') { + if (logData.attributes?.['event.name']?.includes('tool')) { + console.log(`[TestRig] Found tool-related log: ${JSON.stringify(logData.attributes)}`); + } + } // Look for tool call logs if ( logData.attributes && @@ -1397,6 +1416,11 @@ export class TestRig { }[] = []; for (const logData of parsedLogs) { + if (env['VERBOSE'] === 'true' || env['CI'] === 'true') { + if (logData.attributes?.['event.name']?.includes('hook')) { + console.log(`[TestRig] Found hook-related log: ${JSON.stringify(logData.attributes)}`); + } + } // Look for tool call logs if ( logData.attributes &&