repro: use simple echo hook and re-enable rich logging

This commit is contained in:
Taylor Mullen
2026-02-10 16:37:18 -08:00
parent 1780234b13
commit 6655b0afd4
5 changed files with 77 additions and 22 deletions
+21 -22
View File
@@ -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,
);
});
@@ -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));
+10
View File
@@ -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;
+18
View File
@@ -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 {
+24
View File
@@ -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 &&