diff --git a/core/src/index.ts b/core/src/index.ts index 242f18fca..f3e664e63 100644 --- a/core/src/index.ts +++ b/core/src/index.ts @@ -4,6 +4,16 @@ * SPDX-License-Identifier: Apache-2.0 */ +import {installNodeLogger} from './utils/logger_node.js'; + +// The Node entry point installs the winston-backed logger. `utils/logger.ts` +// itself must stay free of Node-only imports so that the browser entry point +// can reach it; see https://github.com/google/adk-js/issues/611. +// This call runs after the modules re-exported below are evaluated, so a module +// must log through the `logger` facade instead of holding the result of +// `getLogger()`. +installNodeLogger(); + export {AGENT_CARD_PATH, RemoteA2AAgent} from './a2a/a2a_remote_agent.js'; export type { A2AStreamEventData, diff --git a/core/src/tools/load_artifacts_tool.ts b/core/src/tools/load_artifacts_tool.ts index 5dd67ebe1..c27ddd26d 100644 --- a/core/src/tools/load_artifacts_tool.ts +++ b/core/src/tools/load_artifacts_tool.ts @@ -8,15 +8,13 @@ import {FunctionDeclaration, Part, Type} from '@google/genai'; import {Context} from '../agents/context.js'; import {appendInstructions, LlmRequest} from '../models/llm_request.js'; -import {getLogger} from '../utils/logger.js'; +import {logger} from '../utils/logger.js'; import { BaseTool, RunAsyncToolRequest, ToolProcessLlmRequest, } from './base_tool.js'; -const logger = getLogger(); - const GEMINI_SUPPORTED_INLINE_MIME_PREFIXES = ['image/', 'audio/', 'video/']; const GEMINI_SUPPORTED_INLINE_MIME_TYPES = new Set(['application/pdf']); const TEXT_LIKE_MIME_TYPES = new Set([ diff --git a/core/src/tools/vertex_ai_search_tool.ts b/core/src/tools/vertex_ai_search_tool.ts index 861ffb78e..f9d8da06f 100644 --- a/core/src/tools/vertex_ai_search_tool.ts +++ b/core/src/tools/vertex_ai_search_tool.ts @@ -6,7 +6,7 @@ import {GenerateContentConfig, Tool} from '@google/genai'; import {ReadonlyContext} from '../agents/readonly_context.js'; -import {getLogger} from '../utils/logger.js'; +import {logger} from '../utils/logger.js'; import { isGemini1Model, isGeminiModel, @@ -14,8 +14,6 @@ import { } from '../utils/model_name.js'; import {BaseTool, ToolProcessLlmRequest} from './base_tool.js'; -const logger = getLogger(); - export interface VertexAISearchDataStoreSpec { dataStore?: string; } diff --git a/core/src/utils/logger.ts b/core/src/utils/logger.ts index dc854e7ec..1293ada81 100644 --- a/core/src/utils/logger.ts +++ b/core/src/utils/logger.ts @@ -3,7 +3,6 @@ * Copyright 2025 Google LLC * SPDX-License-Identifier: Apache-2.0 */ -import * as winston from 'winston'; /** Log levels for the logger. */ export enum LogLevel { @@ -30,35 +29,24 @@ export interface Logger { setLogLevel(level: LogLevel): void; } +/** The `console` method each level is written with. */ +const CONSOLE_METHOD = { + [LogLevel.DEBUG]: 'debug', + [LogLevel.INFO]: 'info', + [LogLevel.WARN]: 'warn', + [LogLevel.ERROR]: 'error', +} as const; + +/** + * The default logger. Writes through `console` so that it works unchanged in + * Node and in the browser. This module is reachable from the browser entry + * point, so it must not name a Node-only package; the Node entry point + * installs the winston-backed logger instead. + * See https://github.com/google/adk-js/issues/611. + */ class SimpleLogger implements Logger { - private readonly logger: winston.Logger; private logLevel: LogLevel = LogLevel.INFO; - constructor() { - this.logger = winston.createLogger({ - levels: { - 'debug': LogLevel.DEBUG, - 'info': LogLevel.INFO, - 'warn': LogLevel.WARN, - 'error': LogLevel.ERROR, - }, - level: 'error', - format: winston.format.combine( - winston.format.label({label: 'ADK'}), - winston.format((info) => { - info.level = info.level.toUpperCase(); - return info; - })(), - winston.format.colorize(), - winston.format.timestamp(), - winston.format.printf((info) => { - return `${info.level}: [${info.label}] ${info.timestamp} ${info.message}`; - }), - ), - transports: [new winston.transports.Console()], - }); - } - setLogLevel(level: LogLevel): void { this.logLevel = level; } @@ -68,39 +56,26 @@ class SimpleLogger implements Logger { return; } - this.logger.log(level.toString(), messages.join(' ')); + const timestamp = new Date().toISOString(); + const line = `${LogLevel[level]}: [ADK] ${timestamp} ${messages.join(' ')}`; + + console[CONSOLE_METHOD[level]](line); } debug(...messages: unknown[]): void { - if (this.logLevel > LogLevel.DEBUG) { - return; - } - - this.logger.debug(messages.join(' ')); + this.log(LogLevel.DEBUG, ...messages); } info(...messages: unknown[]): void { - if (this.logLevel > LogLevel.INFO) { - return; - } - - this.logger.info(messages.join(' ')); + this.log(LogLevel.INFO, ...messages); } warn(...messages: unknown[]): void { - if (this.logLevel > LogLevel.WARN) { - return; - } - - this.logger.warn(messages.join(' ')); + this.log(LogLevel.WARN, ...messages); } error(...messages: unknown[]): void { - if (this.logLevel > LogLevel.ERROR) { - return; - } - - this.logger.error(messages.join(' ')); + this.log(LogLevel.ERROR, ...messages); } } @@ -133,7 +108,8 @@ export function getLogger(): Logger { } /** - * Resets the logger to the default SimpleLogger. + * Resets the logger to the built-in console logger. On Node this replaces the + * winston-backed logger that the Node entry point installs. */ export function resetLogger(): void { currentLogger = new SimpleLogger(); diff --git a/core/src/utils/logger_node.ts b/core/src/utils/logger_node.ts new file mode 100644 index 000000000..d9975fee1 --- /dev/null +++ b/core/src/utils/logger_node.ts @@ -0,0 +1,98 @@ +/** + * @license + * Copyright 2026 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * The Node-only logger implementation. + * + * This module is the only place under `core/src` that may name `winston`. + * `winston` needs Node built-ins, so no browser bundler can resolve it: this + * module must never become reachable from `core/src/index_web.ts`. The Node + * entry point (`core/src/index.ts`) wires it in through `setLogger`. + * See https://github.com/google/adk-js/issues/611. + */ + +import * as winston from 'winston'; +import {Logger, LogLevel, setLogger} from './logger.js'; + +/** The default logger on Node. Writes through winston. */ +export class WinstonLogger implements Logger { + private readonly logger: winston.Logger; + private logLevel: LogLevel = LogLevel.INFO; + + constructor() { + this.logger = winston.createLogger({ + levels: { + 'debug': LogLevel.DEBUG, + 'info': LogLevel.INFO, + 'warn': LogLevel.WARN, + 'error': LogLevel.ERROR, + }, + level: 'error', + format: winston.format.combine( + winston.format.label({label: 'ADK'}), + winston.format((info) => { + info.level = info.level.toUpperCase(); + return info; + })(), + winston.format.colorize(), + winston.format.timestamp(), + winston.format.printf((info) => { + return `${info.level}: [${info.label}] ${info.timestamp} ${info.message}`; + }), + ), + transports: [new winston.transports.Console()], + }); + } + + setLogLevel(level: LogLevel): void { + this.logLevel = level; + } + + log(level: LogLevel, ...messages: unknown[]): void { + if (this.logLevel > level) { + return; + } + + this.logger.log(level.toString(), messages.join(' ')); + } + + debug(...messages: unknown[]): void { + if (this.logLevel > LogLevel.DEBUG) { + return; + } + + this.logger.debug(messages.join(' ')); + } + + info(...messages: unknown[]): void { + if (this.logLevel > LogLevel.INFO) { + return; + } + + this.logger.info(messages.join(' ')); + } + + warn(...messages: unknown[]): void { + if (this.logLevel > LogLevel.WARN) { + return; + } + + this.logger.warn(messages.join(' ')); + } + + error(...messages: unknown[]): void { + if (this.logLevel > LogLevel.ERROR) { + return; + } + + this.logger.error(messages.join(' ')); + } +} + +/** Makes the winston-backed logger the current ADK logger. */ +export function installNodeLogger(): void { + setLogger(new WinstonLogger()); +} diff --git a/core/test/tools/tool_logging_test.ts b/core/test/tools/tool_logging_test.ts new file mode 100644 index 000000000..da829477b --- /dev/null +++ b/core/test/tools/tool_logging_test.ts @@ -0,0 +1,188 @@ +/** + * @license + * Copyright 2026 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { + Context, + InMemoryArtifactService, + InMemorySessionService, + InvocationContext, + LlmAgent, + LlmRequest, + LOAD_ARTIFACTS, + Logger, + LogLevel, + PluginManager, + setLogger, + setLogLevel, + VertexAiSearchTool, +} from '@google/adk'; +import {afterEach, beforeEach, describe, expect, it, vi} from 'vitest'; +// ScopedArtifactService is how the runner scopes an artifact service to one +// session, and it is not part of the public surface. +import {ScopedArtifactService} from '../../src/artifacts/scoped_artifact_service.js'; +import {resetLogger} from '../../src/utils/logger.js'; +import {installNodeLogger} from '../../src/utils/logger_node.js'; + +const APP_NAME = 'logging-test-app'; +const USER_ID = 'logging-test-user'; + +/** A record of one call made on the {@link RecordingLogger}. */ +interface LogRecord { + level: LogLevel; + message: string; +} + +/** A {@link Logger} that keeps every record it is given. */ +class RecordingLogger implements Logger { + readonly records: LogRecord[] = []; + + setLogLevel(_level: LogLevel): void {} + + log(level: LogLevel, ...messages: unknown[]): void { + this.records.push({level, message: messages.join(' ')}); + } + + debug(...messages: unknown[]): void { + this.log(LogLevel.DEBUG, ...messages); + } + + info(...messages: unknown[]): void { + this.log(LogLevel.INFO, ...messages); + } + + warn(...messages: unknown[]): void { + this.log(LogLevel.WARN, ...messages); + } + + error(...messages: unknown[]): void { + this.log(LogLevel.ERROR, ...messages); + } +} + +/** Builds a real invocation context backed by the in-memory services. */ +async function createInvocationContext(): Promise { + const sessionService = new InMemorySessionService(); + const session = await sessionService.createSession({ + appName: APP_NAME, + userId: USER_ID, + }); + const artifactService = new InMemoryArtifactService(); + await artifactService.saveArtifact({ + appName: APP_NAME, + userId: USER_ID, + sessionId: session.id, + filename: 'present.txt', + artifact: {text: 'hello'}, + }); + + return new InvocationContext({ + invocationId: 'logging-test-invocation', + agent: new LlmAgent({name: 'logging_test_agent'}), + session, + sessionService, + artifactService: new ScopedArtifactService( + artifactService, + APP_NAME, + USER_ID, + session.id, + ), + pluginManager: new PluginManager(), + }); +} + +/** A request that asks `load_artifacts` for an artifact that does not exist. */ +function createMissingArtifactRequest(): LlmRequest { + return { + contents: [ + { + role: 'user', + parts: [ + { + functionResponse: { + name: 'load_artifacts', + response: {artifact_names: ['missing.txt']}, + }, + }, + ], + }, + ], + toolsDict: {}, + liveConnectConfig: {}, + }; +} + +describe('tool logging', () => { + let toolContext: Context; + + beforeEach(async () => { + toolContext = new Context({ + invocationContext: await createInvocationContext(), + }); + installNodeLogger(); + }); + + afterEach(() => { + vi.restoreAllMocks(); + resetLogger(); + }); + + describe('LoadArtifactsTool', () => { + it('sends the missing-artifact warning to the current logger', async () => { + const recorded = new RecordingLogger(); + setLogger(recorded); + + await LOAD_ARTIFACTS.processLlmRequest({ + toolContext, + llmRequest: createMissingArtifactRequest(), + }); + + expect(recorded.records).toEqual([ + { + level: LogLevel.WARN, + message: 'Artifact "missing.txt" not found, skipping', + }, + ]); + }); + + it('drops the missing-artifact warning at ERROR level', async () => { + const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + setLogLevel(LogLevel.ERROR); + + await LOAD_ARTIFACTS.processLlmRequest({ + toolContext, + llmRequest: createMissingArtifactRequest(), + }); + + expect(warnSpy).not.toHaveBeenCalled(); + }); + }); + + describe('VertexAiSearchTool', () => { + it('sends the search-config debug line to the current logger', async () => { + const recorded = new RecordingLogger(); + setLogger(recorded); + + await new VertexAiSearchTool({dataStoreId: 'ds'}).processLlmRequest({ + toolContext, + llmRequest: { + model: 'gemini-2.0-flash', + contents: [], + toolsDict: {}, + liveConnectConfig: {}, + }, + }); + + expect(recorded.records).toEqual([ + { + level: LogLevel.DEBUG, + message: expect.stringContaining( + 'Adding Vertex AI Search tool config to LLM request', + ), + }, + ]); + }); + }); +}); diff --git a/core/test/utils/logger_node_test.ts b/core/test/utils/logger_node_test.ts new file mode 100644 index 000000000..cf73546c7 --- /dev/null +++ b/core/test/utils/logger_node_test.ts @@ -0,0 +1,152 @@ +/** + * @license + * Copyright 2026 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import {afterEach, beforeEach, describe, expect, it, vi} from 'vitest'; +import { + getLogger, + LogLevel, + resetLogger, + setLogLevel, +} from '../../src/utils/logger.js'; +import {installNodeLogger, WinstonLogger} from '../../src/utils/logger_node.js'; + +/** The escape character that opens an ANSI colour code. */ +const ESC = String.fromCharCode(27); + +/** The colour codes `winston.format.colorize()` wraps the level in. */ +const ANSI_ESCAPE = new RegExp(`${ESC}\\[\\d+m`, 'g'); + +/** + * Node keeps the stream behind `console` on an internal field, and winston's + * Console transport writes straight to it. Vitest installs its own `console`, + * so capturing the output means spying on that stream rather than on + * `process.stdout`. + */ +type ConsoleWithStdout = typeof console & { + _stdout?: {write(chunk: string): boolean}; +}; + +/** Lines the Console transport wrote during the test. */ +let lines: string[] = []; + +/** Lets winston's stream pipeline flush before the assertions run. */ +function flush(): Promise { + return new Promise((resolve) => setImmediate(resolve)); +} + +function stripAnsi(line: string): string { + return line.replace(ANSI_ESCAPE, ''); +} + +describe('WinstonLogger', () => { + beforeEach(() => { + lines = []; + const consoleWithStdout: ConsoleWithStdout = console; + const stdout = consoleWithStdout._stdout; + if (!stdout) { + expect.fail('console has no _stdout stream to capture'); + } + vi.spyOn(stdout, 'write').mockImplementation((chunk: string) => { + lines.push(chunk); + return true; + }); + installNodeLogger(); + }); + + afterEach(() => { + vi.restoreAllMocks(); + resetLogger(); + }); + + it('is installed by installNodeLogger()', () => { + expect(getLogger()).toBeInstanceOf(WinstonLogger); + }); + + it('writes the ADK line format', async () => { + setLogLevel(LogLevel.ERROR); + + getLogger().error('boom'); + await flush(); + + expect(lines).toHaveLength(1); + expect(stripAnsi(lines[0]).trimEnd()).toMatch( + /^ERROR: \[ADK\] \d{4}-\d{2}-\d{2}T[\d:.]+Z boom$/, + ); + }); + + it('colorizes the level', async () => { + setLogLevel(LogLevel.ERROR); + + getLogger().error('boom'); + await flush(); + + expect(lines[0]).toContain(`${ESC}[`); + }); + + it('suppresses the levels below the configured level', async () => { + setLogLevel(LogLevel.WARN); + + getLogger().debug('d'); + getLogger().info('i'); + await flush(); + + expect(lines).toHaveLength(0); + + getLogger().warn('w'); + getLogger().error('e'); + await flush(); + + expect(lines.map((line) => stripAnsi(line).trimEnd())).toEqual([ + expect.stringMatching(/^WARN: \[ADK\] .* w$/), + expect.stringMatching(/^ERROR: \[ADK\] .* e$/), + ]); + }); + + it('writes a debug line when the level allows it', async () => { + setLogLevel(LogLevel.DEBUG); + + getLogger().debug('trace'); + await flush(); + + expect(stripAnsi(lines[0]).trimEnd()).toMatch(/^DEBUG: \[ADK\] .* trace$/); + }); + + it('suppresses a warning below the configured level', async () => { + setLogLevel(LogLevel.ERROR); + + getLogger().warn('w'); + await flush(); + + expect(lines).toHaveLength(0); + }); + + it('joins arguments with a single space', async () => { + setLogLevel(LogLevel.INFO); + + getLogger().info('a', 1, true); + await flush(); + + expect(stripAnsi(lines[0]).trimEnd()).toMatch(/ a 1 true$/); + }); + + it('drops a log() call below the configured level', async () => { + setLogLevel(LogLevel.ERROR); + + getLogger().log(LogLevel.INFO, 'quiet'); + await flush(); + + expect(lines).toHaveLength(0); + }); + + it('throws from log() because winston rejects the numeric level name', () => { + setLogLevel(LogLevel.ERROR); + + // Pre-existing behaviour, preserved by this change: `log()` passes the + // numeric enum value to winston, which knows only the 'debug'..'error' + // names. A separate change fixes it. + expect(() => getLogger().log(LogLevel.ERROR, 'boom')).toThrow(); + }); +}); diff --git a/core/test/utils/logger_node_wiring_test.ts b/core/test/utils/logger_node_wiring_test.ts new file mode 100644 index 000000000..5a33c4033 --- /dev/null +++ b/core/test/utils/logger_node_wiring_test.ts @@ -0,0 +1,19 @@ +/** + * @license + * Copyright 2026 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import {getLogger} from '@google/adk'; +import {describe, expect, it} from 'vitest'; +import {WinstonLogger} from '../../src/utils/logger_node.js'; + +/** + * Nothing in this file may call `resetLogger()` or `setLogger()`: the point is + * that importing the Node entry point is what installs the winston logger. + */ +describe('Node entry point', () => { + it('installs the winston logger on import', () => { + expect(getLogger()).toBeInstanceOf(WinstonLogger); + }); +}); diff --git a/core/test/utils/logger_test.ts b/core/test/utils/logger_test.ts index 2865a9de0..bbb2b0b4d 100644 --- a/core/test/utils/logger_test.ts +++ b/core/test/utils/logger_test.ts @@ -5,9 +5,19 @@ */ import {getLogger, Logger, LogLevel, setLogger, setLogLevel} from '@google/adk'; -import {afterEach, beforeEach, describe, expect, it} from 'vitest'; +import {readFile} from 'node:fs/promises'; +import {fileURLToPath} from 'node:url'; +import {afterEach, beforeEach, describe, expect, it, vi} from 'vitest'; import {resetLogger} from '../../src/utils/logger.js'; +/** Reads a module under `core/src/utils` as text. */ +function readCoreSource(name: string): Promise { + return readFile( + fileURLToPath(new URL(`../../src/utils/${name}`, import.meta.url)), + 'utf8', + ); +} + describe('setLogger', () => { beforeEach(() => { resetLogger(); @@ -142,3 +152,138 @@ describe('setLogger', () => { }); }); }); + +describe('SimpleLogger', () => { + const ISO_TIMESTAMP = String.raw`\d{4}-\d{2}-\d{2}T[\d:.]+Z`; + + beforeEach(() => { + resetLogger(); + }); + + afterEach(() => { + vi.restoreAllMocks(); + resetLogger(); + }); + + it('emits a message at the configured level', () => { + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + setLogLevel(LogLevel.INFO); + + getLogger().info('hello'); + + expect(infoSpy).toHaveBeenCalledTimes(1); + expect(infoSpy).toHaveBeenCalledWith( + expect.stringMatching( + new RegExp(`^INFO: \\[ADK\\] ${ISO_TIMESTAMP} hello$`), + ), + ); + }); + + it('suppresses a message below the configured level', () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + setLogLevel(LogLevel.WARN); + + getLogger().debug('x'); + getLogger().info('y'); + + expect(debugSpy).not.toHaveBeenCalled(); + expect(infoSpy).not.toHaveBeenCalled(); + + getLogger().warn('z'); + + expect(warnSpy).toHaveBeenCalledTimes(1); + }); + + it('defaults to INFO', () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + + getLogger().debug('x'); + getLogger().info('y'); + + expect(debugSpy).not.toHaveBeenCalled(); + expect(infoSpy).toHaveBeenCalledTimes(1); + }); + + it('routes each level to its matching console method', () => { + const debugSpy = vi.spyOn(console, 'debug').mockImplementation(() => {}); + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + const errorSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); + setLogLevel(LogLevel.DEBUG); + + getLogger().debug('d'); + getLogger().info('i'); + getLogger().warn('w'); + getLogger().error('e'); + + expect(debugSpy).toHaveBeenCalledTimes(1); + expect(debugSpy).toHaveBeenCalledWith( + expect.stringContaining('DEBUG: [ADK] '), + ); + expect(infoSpy).toHaveBeenCalledTimes(1); + expect(infoSpy).toHaveBeenCalledWith( + expect.stringContaining('INFO: [ADK] '), + ); + expect(warnSpy).toHaveBeenCalledTimes(1); + expect(warnSpy).toHaveBeenCalledWith( + expect.stringContaining('WARN: [ADK] '), + ); + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy).toHaveBeenCalledWith( + expect.stringContaining('ERROR: [ADK] '), + ); + }); + + it('joins arguments with a single space', () => { + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + setLogLevel(LogLevel.INFO); + + getLogger().info('a', 1, true); + + expect(infoSpy).toHaveBeenCalledWith( + expect.stringMatching( + new RegExp(`^INFO: \\[ADK\\] ${ISO_TIMESTAMP} a 1 true$`), + ), + ); + }); + + it('log() emits without throwing', () => { + const infoSpy = vi.spyOn(console, 'info').mockImplementation(() => {}); + setLogLevel(LogLevel.INFO); + + expect(() => getLogger().log(LogLevel.INFO, 'via log')).not.toThrow(); + expect(infoSpy).toHaveBeenCalledTimes(1); + expect(infoSpy).toHaveBeenCalledWith(expect.stringContaining('via log')); + }); + + it('formats the full line for a warning', () => { + const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); + setLogLevel(LogLevel.WARN); + + getLogger().warn('boom'); + + expect(warnSpy).toHaveBeenCalledWith( + expect.stringMatching( + new RegExp(`^WARN: \\[ADK\\] ${ISO_TIMESTAMP} boom$`), + ), + ); + }); +}); + +describe('browser safety', () => { + it('keeps the browser-reachable logger free of imports', async () => { + const source = await readCoreSource('logger.ts'); + + expect(source).not.toMatch(/^\s*import\b/m); + expect(source).not.toMatch(/\bimport\(/); + }); + + it('keeps winston in the Node-only logger', async () => { + const source = await readCoreSource('logger_node.ts'); + + expect(source).toMatch(/from 'winston'/); + }); +});