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

This commit is contained in:
Taylor Mullen
2026-02-11 09:21:00 -08:00
parent 608364b207
commit 458e41a79a
5 changed files with 95 additions and 39 deletions
+39 -39
View File
@@ -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,
},
],
},
@@ -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,
@@ -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 {
+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 &&