diff --git a/integration-tests/hooks-system.test.ts b/integration-tests/hooks-system.test.ts index 032c1f5c3a..0114514c7f 100644 --- a/integration-tests/hooks-system.test.ts +++ b/integration-tests/hooks-system.test.ts @@ -521,7 +521,7 @@ console.log(JSON.stringify({ // 1. Initial setup to establish test directory rig.setup('BeforeToolSelection Hooks'); - const toolConfigJson = JSON.stringify({ + const toolConfigJson = { hookSpecificOutput: { hookEventName: 'BeforeToolSelection', toolConfig: { @@ -529,10 +529,12 @@ console.log(JSON.stringify({ allowedFunctionNames: ['read_file'], }, }, - }); + }; - // Use node -e to avoid file system and PTY overhead - const nodeCmd = `node -e "console.log(JSON.stringify(${toolConfigJson.replace(/"/g, '\\"')}))"`; + const scriptPath = rig.createScript( + 'before_tool_selection_hook.cjs', + `console.log(JSON.stringify(${JSON.stringify(toolConfigJson)}));`, + ); rig.setup('BeforeToolSelection Hooks', { fakeResponsesPath: join( @@ -548,8 +550,8 @@ console.log(JSON.stringify({ hooks: [ { type: 'command', - command: nodeCmd, - timeout: 15000, + command: normalizePath(`node "${scriptPath}"`)!, + timeout: 30000, }, ], }, @@ -1770,18 +1772,18 @@ console.log(JSON.stringify({ const enabledMsg = 'EXECUTION_ALLOWED_BY_HOOK_A'; const disabledMsg = 'EXECUTION_BLOCKED_BY_HOOK_B'; - const enabledJson = JSON.stringify({ - decision: 'allow', - systemMessage: enabledMsg, - }); - const disabledJson = JSON.stringify({ - decision: 'block', - reason: disabledMsg, - }); + const enabledPath = rig.createScript( + 'enabled_hook.cjs', + `console.log(JSON.stringify({decision: "allow", systemMessage: "${enabledMsg}"}));`, + ); - // Use node -e to avoid file system and PTY overhead - const enabledCmd = `node -e "console.log(JSON.stringify(${enabledJson.replace(/"/g, '\\"')}))"`; - const disabledCmd = `node -e "console.log(JSON.stringify(${disabledJson.replace(/"/g, '\\"')}))"`; + const disabledPath = rig.createScript( + 'disabled_hook.cjs', + `console.log(JSON.stringify({decision: "block", reason: "${disabledMsg}"}));`, + ); + + const normalizedDisabledCmd = normalizePath(`node "${disabledPath}"`); + const normalizedEnabledCmd = normalizePath(`node "${enabledPath}"`); // 3. Final setup with full settings rig.setup('Hook Disabling', { @@ -1791,20 +1793,20 @@ console.log(JSON.stringify({ ), settings: { enableHooks: true, - disabledHooks: [disabledCmd], + disabledHooks: [normalizedDisabledCmd!], hooks: { BeforeTool: [ { hooks: [ { type: 'command', - command: enabledCmd, - timeout: 15000, + command: normalizedEnabledCmd!, + timeout: 30000, }, { type: 'command', - command: disabledCmd, - timeout: 15000, + command: normalizedDisabledCmd!, + timeout: 30000, }, ], }, @@ -1835,43 +1837,41 @@ console.log(JSON.stringify({ }); it.only('should respect disabled hooks across multiple operations', async () => { - // 1. Initial setup to establish test directory rig.setup('Hook Disabling'); const activeMsg = 'MULTIPLE_OPS_ENABLED_HOOK'; const disabledMsg = 'MULTIPLE_OPS_DISABLED_HOOK'; - const activeJson = JSON.stringify({ - decision: 'allow', - systemMessage: activeMsg, - }); - const disabledJson = JSON.stringify({ - decision: 'block', - reason: disabledMsg, - }); + const activePath = rig.createScript( + 'active_hook.cjs', + `console.log(JSON.stringify({decision: "allow", systemMessage: "${activeMsg}"}));`, + ); + const disabledPath = rig.createScript( + 'disabled_hook.cjs', + `console.log(JSON.stringify({decision: "block", reason: "${disabledMsg}"}));`, + ); - // Use node -e to avoid file system and PTY overhead - const activeCmd = `node -e "console.log(JSON.stringify(${activeJson.replace(/"/g, '\\"')}))"`; - const disabledCmd = `node -e "console.log(JSON.stringify(${disabledJson.replace(/"/g, '\\"')}))"`; + const normalizedDisabledCmd = normalizePath(`node "${disabledPath}"`); + const normalizedActiveCmd = normalizePath(`node "${activePath}"`); // 3. Final setup with full settings rig.setup('Hook Disabling', { settings: { enableHooks: true, - disabledHooks: [disabledCmd], + disabledHooks: [normalizedDisabledCmd!], hooks: { BeforeTool: [ { hooks: [ { type: 'command', - command: activeCmd, - timeout: 15000, + command: normalizedActiveCmd!, + timeout: 30000, }, { type: 'command', - command: disabledCmd, - timeout: 15000, + command: normalizedDisabledCmd!, + timeout: 30000, }, ], }, 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 b5a3325f4d..4a1926f79d 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, @@ -428,6 +443,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 &&