From 8c1e255ac077f5c3b24d0464d4f5a514f855ef9a Mon Sep 17 00:00:00 2001 From: Coco Sheng Date: Thu, 30 Apr 2026 14:34:25 -0400 Subject: [PATCH] fix(cli): prevent informational logs from polluting json output (#26264) --- packages/cli/src/gemini.tsx | 63 ++++++++---- packages/cli/src/output-redirection.test.ts | 100 ++++++++++++++++++++ packages/core/src/utils/events.test.ts | 56 +++++++++++ packages/core/src/utils/events.ts | 24 ++++- 4 files changed, 219 insertions(+), 24 deletions(-) create mode 100644 packages/cli/src/output-redirection.test.ts diff --git a/packages/cli/src/gemini.tsx b/packages/cli/src/gemini.tsx index 1319ec8194..b9cda80d8b 100644 --- a/packages/cli/src/gemini.tsx +++ b/packages/cli/src/gemini.tsx @@ -13,6 +13,7 @@ import { type OutputPayload, type ConsoleLogPayload, type UserFeedbackPayload, + type CoreEvents, createSessionId, logUserPrompt, AuthType, @@ -265,6 +266,7 @@ export async function startInteractiveUI( } export async function main() { + let config: Config | undefined; const cliStartupHandle = startupProfiler.start('cli_startup'); // Listen for admin controls from parent process (IPC) in non-sandbox mode. In @@ -277,7 +279,7 @@ export async function main() { const cleanupStdio = patchStdio(); registerSyncCleanup(() => { // This is needed to ensure we don't lose any buffered output. - initializeOutputListenersAndFlush(); + initializeOutputListenersAndFlush(config); cleanupStdio(); }); @@ -539,7 +541,7 @@ export async function main() { // may have side effects. { const loadConfigHandle = startupProfiler.start('load_cli_config'); - const config = await loadCliConfig(settings.merged, sessionId, argv, { + config = await loadCliConfig(settings.merged, sessionId, argv, { projectHooks: settings.workspace.settings.hooks, worktreeSettings: worktreeInfo, }); @@ -785,7 +787,7 @@ export async function main() { debugLogger.log('Session ID: %s', sessionId); } - initializeOutputListenersAndFlush(); + initializeOutputListenersAndFlush(config); await runNonInteractive({ config, @@ -800,7 +802,7 @@ export async function main() { } } -export function initializeOutputListenersAndFlush() { +export function initializeOutputListenersAndFlush(config?: Config) { // If there are no listeners for output, make sure we flush so output is not // lost. if (coreEvents.listenerCount(CoreEvent.Output) === 0) { @@ -812,24 +814,43 @@ export function initializeOutputListenersAndFlush() { writeToStdout(payload.chunk, payload.encoding); } }); - - if (coreEvents.listenerCount(CoreEvent.ConsoleLog) === 0) { - coreEvents.on(CoreEvent.ConsoleLog, (payload: ConsoleLogPayload) => { - if (payload.type === 'error' || payload.type === 'warn') { - writeToStderr(payload.content + '\n'); - } else { - writeToStderr(payload.content + '\n'); - } - }); - } - - if (coreEvents.listenerCount(CoreEvent.UserFeedback) === 0) { - coreEvents.on(CoreEvent.UserFeedback, (payload: UserFeedbackPayload) => { - writeToStderr(payload.message + '\n'); - }); - } } - coreEvents.drainBacklogs(); + + if (coreEvents.listenerCount(CoreEvent.ConsoleLog) === 0) { + coreEvents.on(CoreEvent.ConsoleLog, (payload: ConsoleLogPayload) => { + if (payload.type === 'error' || payload.type === 'warn') { + writeToStderr(payload.content + '\n'); + } else { + writeToStderr(payload.content + '\n'); + } + }); + } + + if (coreEvents.listenerCount(CoreEvent.UserFeedback) === 0) { + coreEvents.on(CoreEvent.UserFeedback, (payload: UserFeedbackPayload) => { + writeToStderr(payload.message + '\n'); + }); + } + + const outputFormat = config?.getOutputFormat(); + const forceToStderr = outputFormat === 'json' || config === undefined; + + coreEvents.drainBacklogs( + (event: K, args: CoreEvents[K]) => { + if (forceToStderr && event === (CoreEvent.Output as string)) { + // eslint-disable-next-line @typescript-eslint/no-unsafe-type-assertion + const payload = args[0] as OutputPayload; + if (!payload.isStderr) { + return { + event, + // eslint-disable-next-line @typescript-eslint/no-unsafe-type-assertion + args: [{ ...payload, isStderr: true }] as unknown as CoreEvents[K], + }; + } + } + return { event, args }; + }, + ); } function setupAdminControlsListener() { diff --git a/packages/cli/src/output-redirection.test.ts b/packages/cli/src/output-redirection.test.ts new file mode 100644 index 0000000000..2dc935b330 --- /dev/null +++ b/packages/cli/src/output-redirection.test.ts @@ -0,0 +1,100 @@ +/** + * @license + * Copyright 2026 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { initializeOutputListenersAndFlush } from './gemini.js'; +import { coreEvents, CoreEvent, type Config } from '@google/gemini-cli-core'; + +// Mock core dependencies +vi.mock('@google/gemini-cli-core', async (importOriginal) => { + const actual = + await importOriginal(); + return { + ...actual, + writeToStdout: vi.fn(), + writeToStderr: vi.fn(), + }; +}); + +import { writeToStdout, writeToStderr } from '@google/gemini-cli-core'; + +describe('Output Redirection', () => { + beforeEach(() => { + vi.clearAllMocks(); + // Clear listeners to simulate a clean state for each test + coreEvents.removeAllListeners(); + }); + + afterEach(() => { + coreEvents.removeAllListeners(); + }); + + it('should redirect buffered stdout to stderr when output format is json', () => { + const mockConfig = { + getOutputFormat: () => 'json', + } as unknown as Config; + + // Simulate buffered output + coreEvents.emitOutput(false, 'informational message'); + coreEvents.emitOutput(true, 'error message'); + + // Initialize listeners and flush + initializeOutputListenersAndFlush(mockConfig); + + // Verify informational message was forced to stderr + expect(writeToStderr).toHaveBeenCalledWith( + 'informational message', + undefined, + ); + expect(writeToStderr).toHaveBeenCalledWith('error message', undefined); + expect(writeToStdout).not.toHaveBeenCalled(); + }); + + it('should NOT redirect buffered stdout to stderr when output format is NOT json', () => { + const mockConfig = { + getOutputFormat: () => 'text', + } as unknown as Config; + + // Simulate buffered output + coreEvents.emitOutput(false, 'regular message'); + + // Initialize listeners and flush + initializeOutputListenersAndFlush(mockConfig); + + // Verify regular message went to stdout + expect(writeToStdout).toHaveBeenCalledWith('regular message', undefined); + expect(writeToStderr).not.toHaveBeenCalled(); + }); + + it('should force stdout to stderr when config is undefined (early failure)', () => { + // Simulate buffered output during early init + coreEvents.emitOutput(false, 'early init message'); + + // Initialize with undefined config + initializeOutputListenersAndFlush(undefined); + + // Verify it was forced to stderr + expect(writeToStderr).toHaveBeenCalledWith('early init message', undefined); + expect(writeToStdout).not.toHaveBeenCalled(); + }); + + it('should attach ConsoleLog and UserFeedback listeners even if Output already has one', () => { + // Manually attach an Output listener + coreEvents.on(CoreEvent.Output, vi.fn()); + + // Initialize - should still attach ConsoleLog and UserFeedback defaults + initializeOutputListenersAndFlush(undefined); + + // Simulate events + coreEvents.emitConsoleLog('info', 'stray log'); + coreEvents.emitFeedback('info', 'stray feedback'); + + // Draining happens inside initializeOutputListenersAndFlush for existing backlog, + // but here we check the newly attached listeners for immediate emission. + expect(writeToStderr).toHaveBeenCalledWith('stray log\n'); + expect(writeToStderr).toHaveBeenCalledWith('stray feedback\n'); + }); +}); diff --git a/packages/core/src/utils/events.test.ts b/packages/core/src/utils/events.test.ts index 82be02f12a..4e9140a0ee 100644 --- a/packages/core/src/utils/events.test.ts +++ b/packages/core/src/utils/events.test.ts @@ -9,6 +9,7 @@ import { CoreEventEmitter, CoreEvent, coreEvents, + type CoreEvents, type UserFeedbackPayload, type McpProgressPayload, } from './events.js'; @@ -268,6 +269,61 @@ describe('CoreEventEmitter', () => { }); }); + describe('drainBacklogs Transformation', () => { + it('should transform events during drain', () => { + const listener = vi.fn(); + events.emitOutput(false, 'stdout chunk'); + events.emitFeedback('info', 'info message'); + + events.on(CoreEvent.Output, listener); + events.on(CoreEvent.UserFeedback, listener); + + events.drainBacklogs( + (event: K, args: CoreEvents[K]) => { + if (event === (CoreEvent.Output as string)) { + const payload = args[0] as { isStderr: boolean; chunk: string }; + return { + event, + args: [ + { ...payload, isStderr: true }, + ] as unknown as CoreEvents[K], + }; + } + return { event, args }; + }, + ); + + expect(listener).toHaveBeenCalledTimes(2); + expect(listener).toHaveBeenCalledWith( + expect.objectContaining({ isStderr: true, chunk: 'stdout chunk' }), + ); + expect(listener).toHaveBeenCalledWith( + expect.objectContaining({ message: 'info message' }), + ); + }); + + it('should drop events when transform returns undefined', () => { + const listener = vi.fn(); + events.emitOutput(false, 'drop me'); + events.emitFeedback('info', 'keep me'); + + events.on(CoreEvent.Output, listener); + events.on(CoreEvent.UserFeedback, listener); + + events.drainBacklogs((event, args) => { + if (event === CoreEvent.Output) { + return undefined; + } + return { event, args }; + }); + + expect(listener).toHaveBeenCalledTimes(1); + expect(listener).toHaveBeenCalledWith( + expect.objectContaining({ message: 'keep me' }), + ); + }); + }); + describe('ModelChanged Event', () => { it('should emit ModelChanged event with correct payload', () => { const listener = vi.fn(); diff --git a/packages/core/src/utils/events.ts b/packages/core/src/utils/events.ts index 9548146f9d..0a85d466e4 100644 --- a/packages/core/src/utils/events.ts +++ b/packages/core/src/utils/events.ts @@ -422,8 +422,15 @@ export class CoreEventEmitter extends EventEmitter { /** * Flushes buffered messages. Call this immediately after primary UI listener * subscribes. + * + * @param transform - Optional function to transform events before they are emitted. */ - drainBacklogs(): void { + drainBacklogs( + transform?: ( + event: K, + args: CoreEvents[K], + ) => { event: K; args: CoreEvents[K] } | undefined, + ): void { const backlog = this._eventBacklog; const head = this._backlogHead; this._eventBacklog = []; @@ -431,10 +438,21 @@ export class CoreEventEmitter extends EventEmitter { for (let i = head; i < backlog.length; i++) { const item = backlog[i]; if (item === undefined) continue; + + let eventToEmit = item.event; + let argsToEmit = item.args; + + if (transform) { + const transformed = transform(item.event, item.args); + if (!transformed) continue; + eventToEmit = transformed.event; + argsToEmit = transformed.args; + } + // eslint-disable-next-line @typescript-eslint/no-unsafe-type-assertion (this.emit as (event: keyof CoreEvents, ...args: unknown[]) => boolean)( - item.event, - ...item.args, + eventToEmit, + ...argsToEmit, ); } }