import path from 'path'; import chalk from 'chalk'; import { afterEach, beforeEach, describe, expect, it, type Mock, type MockInstance, vi, } from 'vitest'; import { mockProcessEnv } from './util/utils'; import type { Logger } from 'winston'; import type Transport from 'winston-transport'; // Create hoisted mocks const { mockGetEnvString, mockGetEnvBool, mockGetConfigDirectoryPath, fsMock, mockLogger } = vi.hoisted(() => { const mockGetEnvString = vi.fn((_: string, defaultValue: any) => defaultValue); const mockGetEnvBool = vi.fn((_: string, defaultValue: any) => defaultValue); const mockGetConfigDirectoryPath = vi.fn(() => '/mock/config'); const fsMock = { existsSync: vi.fn(), mkdirSync: vi.fn(), readdirSync: vi.fn(), statSync: vi.fn(), unlinkSync: vi.fn(), }; interface MockLogger extends Omit { error: Mock; warn: Mock; info: Mock; debug: Mock; on: Mock; once: Mock; end: Mock; add: Mock; remove: Mock; transports: Array>; } const mockLoggerInstance: MockLogger = { error: vi.fn((info) => { process.stdout.write(chalk.red(info.message)); return mockLoggerInstance; }), warn: vi.fn((info) => { process.stdout.write(chalk.yellow(info.message)); return mockLoggerInstance; }), info: vi.fn((info) => { process.stdout.write(info.message); return mockLoggerInstance; }), debug: vi.fn((info) => { process.stdout.write(chalk.cyan(info.message)); return mockLoggerInstance; }), on: vi.fn(), once: vi.fn((event: string, callback: () => void) => { // Simulate the 'finish' event being emitted after end() is called if (event === 'finish') { setImmediate(callback); } return mockLoggerInstance; }), end: vi.fn(), add: vi.fn(), remove: vi.fn(), transports: [{ level: 'info' }], } as MockLogger; return { mockGetEnvString, mockGetEnvBool, mockGetConfigDirectoryPath, fsMock, mockLogger: mockLoggerInstance, }; }); vi.unmock('../src/logger'); vi.mock('../src/envars', () => ({ getEnvString: mockGetEnvString, getEnvBool: mockGetEnvBool, })); vi.mock('../src/util/config/manage', () => ({ getConfigDirectoryPath: mockGetConfigDirectoryPath, })); vi.mock('fs', () => ({ default: fsMock, ...fsMock, })); // Winston transports need to be classes (constructors) const winstonMock = vi.hoisted(() => { return { createLogger: vi.fn(() => mockLogger), format: { combine: vi.fn(), simple: vi.fn(), printf: vi.fn((cb: (info: Record) => string) => cb), }, transports: { Console: vi.fn(), File: vi.fn().mockImplementation(function (this: { write: ReturnType }) { this.write = vi.fn(); }), }, }; }); vi.mock('winston', () => ({ default: winstonMock, })); describe('logger', () => { let logger: any; let mockStdout: MockInstance; let originalError: typeof Error; beforeEach(async () => { originalError = global.Error; mockStdout = vi.spyOn(process.stdout, 'write').mockImplementation(() => true); vi.clearAllMocks(); mockGetEnvString.mockReset(); mockGetEnvBool.mockReset(); mockGetEnvString.mockImplementation((_, defaultValue) => defaultValue); mockGetEnvBool.mockImplementation((_, defaultValue) => defaultValue); mockGetConfigDirectoryPath.mockReset(); mockGetConfigDirectoryPath.mockReturnValue('/mock/config'); for (const fn of Object.values(fsMock)) { (fn as Mock).mockReset(); } (fsMock.existsSync as Mock).mockReturnValue(true); (fsMock.readdirSync as Mock).mockReturnValue([]); (fsMock.statSync as Mock).mockReturnValue({ mtime: new Date() }); logger = await import('../src/logger'); mockLogger.transports[0].level = 'info'; }); afterEach(async () => { mockStdout.mockRestore(); global.Error = originalError; vi.restoreAllMocks(); vi.doUnmock('source-map-support'); await vi.dynamicImportSettled(); vi.resetModules(); }); describe('logger methods', () => { it('should log messages at different levels', () => { logger.default.error('test error'); expect(mockLogger.error).toHaveBeenCalledWith({ message: 'test error', location: '' }); logger.default.warn('test warning'); expect(mockLogger.warn).toHaveBeenCalledWith({ message: 'test warning', location: '' }); logger.default.info('test info'); expect(mockLogger.info).toHaveBeenCalledWith({ message: 'test info', location: '' }); logger.default.debug('test debug'); expect(mockLogger.debug).toHaveBeenCalledWith({ message: 'test debug', location: expect.any(String), }); }); it('should include location in debug mode', () => { logger.setLogLevel('debug'); const mockStack = `Error at getCallerLocation (file.ts:1:1) at Object. (test.ts:10:20) at logger.test.ts:123:10 at plain/format/path.js:30:5`; // Use a class-based mock for the Error constructor const OriginalError = global.Error; const mockErrorConstructor = function (message?: string) { const error = new OriginalError(message); Object.defineProperty(error, 'stack', { value: mockStack }); return error; }; vi.spyOn(global, 'Error').mockImplementation(mockErrorConstructor as unknown as typeof Error); logger.default.debug('debug message'); expect(mockLogger.debug).toHaveBeenCalledWith({ message: 'debug message', location: '[logger.test.ts:123]', }); }); }); describe('getCallerLocation', () => { it('should return location string with filename and line number', () => { const location = logger.getCallerLocation(); expect(location).toMatch(/\[.*:\d+\]/); }); it('should handle missing stack trace', () => { const mockError = new Error('test error'); Object.defineProperty(mockError, 'stack', { value: undefined }); vi.spyOn(global, 'Error').mockImplementation(() => mockError as Error); const location = logger.getCallerLocation(); expect(location).toBe(''); }); it('should handle different stack trace formats', () => { const mockStack = `Error at getCallerLocation (file.ts:1:1) at Object. (test.ts:10:20) at Object.foo (/absolute/path/file.js:20:10) at plain/format/path.js:30:5`; // Use a class-based mock for the Error constructor const OriginalError = global.Error; const mockErrorConstructor = function (message?: string) { const error = new OriginalError(message); Object.defineProperty(error, 'stack', { value: mockStack }); return error; }; vi.spyOn(global, 'Error').mockImplementation(mockErrorConstructor as unknown as typeof Error); const location = logger.getCallerLocation(); expect(location).toMatch(/\[.*:\d+\]/); }); it('should handle empty stack trace', () => { const mockError = new Error('test error'); Object.defineProperty(mockError, 'stack', { value: '' }); vi.spyOn(global, 'Error').mockImplementation(() => mockError as Error); const location = logger.getCallerLocation(); expect(location).toBe(''); }); it('should handle errors in stack trace parsing', () => { // Force an error in the try block by making stack.split throw const mockError = new Error('test error'); Object.defineProperty(mockError, 'stack', { get: () => { throw new Error('Forced stack access error'); }, }); vi.spyOn(global, 'Error').mockImplementation(() => mockError as Error); const location = logger.getCallerLocation(); expect(location).toBe(''); }); }); describe('consoleFormatter', () => { it('should format messages with colors based on level', () => { const info = { level: 'error', message: 'test error', location: '[test:1]' } as any; const result = logger.consoleFormatter(info); expect(result).toBe(chalk.red('[test:1] test error')); }); it('should format messages without location', () => { const info = { level: 'error', message: 'test error' } as any; const result = logger.consoleFormatter(info); expect(result).toBe(chalk.red('test error')); }); it('should throw error for invalid log level', () => { const info = { level: 'invalid', message: 'test' } as any; expect(() => logger.consoleFormatter(info)).toThrow('Invalid log level: invalid'); }); it('should call global log callback if set', () => { const callback = vi.fn(); logger.setLogCallback(callback); const info = { level: 'info', message: 'test message' } as any; logger.consoleFormatter(info); expect(callback).toHaveBeenCalledWith('test message'); }); it('should handle empty string messages', () => { const info = { level: 'info', message: '' } as any; const result = logger.consoleFormatter(info); expect(result).toBe(''); }); it('should handle nested message objects', () => { const info = { level: 'info', message: { message: 'nested message', location: '[test:1]', }, } as any; const result = logger.consoleFormatter(info); expect(result).toBe('nested message'); }); it('should handle nested empty string messages', () => { const info = { level: 'info', message: { message: '', location: '[test:1]', }, } as any; const result = logger.consoleFormatter(info); expect(result).toBe(''); }); it('should handle non-string message values', () => { const info = { level: 'info', message: 123 } as any; const result = logger.consoleFormatter(info); expect(result).toBe('123'); }); it('should handle non-string nested message values', () => { const info = { level: 'info', message: { message: 123, location: '[test:1]', }, } as any; const result = logger.consoleFormatter(info); expect(result).toBe('123'); }); it('should test all log levels', () => { // Test error level let info = { level: 'error', message: 'error message' } as any; let result = logger.consoleFormatter(info); expect(result).toBe(chalk.red('error message')); // Test warn level info = { level: 'warn', message: 'warning message' } as any; result = logger.consoleFormatter(info); expect(result).toBe(chalk.yellow('warning message')); // Test info level info = { level: 'info', message: 'info message' } as any; result = logger.consoleFormatter(info); expect(result).toBe('info message'); // Test debug level - chalk makes testing exact equality difficult, so check substring info = { level: 'debug', message: 'debug message' } as any; result = logger.consoleFormatter(info); expect(result).toContain('debug message'); }); }); describe('fileFormatter', () => { beforeEach(() => { vi.useFakeTimers(); vi.setSystemTime(new Date('2025-03-01T12:00:00.000Z')); }); afterEach(() => { vi.useRealTimers(); }); it('should format messages with timestamp and level', () => { const info = { level: 'error', message: 'test error', location: '[test:1]' } as any; const result = logger.fileFormatter(info); expect(result).toBe('2025-03-01T12:00:00.000Z [ERROR] [test:1]: test error'); }); it('should format messages without location', () => { const info = { level: 'error', message: 'test error' } as any; const result = logger.fileFormatter(info); expect(result).toBe('2025-03-01T12:00:00.000Z [ERROR]: test error'); }); it('should handle empty string messages', () => { const info = { level: 'error', message: '' } as any; const result = logger.fileFormatter(info); expect(result).toBe('2025-03-01T12:00:00.000Z [ERROR]: '); }); it('should handle nested message objects', () => { const info = { level: 'error', message: { message: 'nested message', location: '[test:1]', }, } as any; const result = logger.fileFormatter(info); expect(result).toBe('2025-03-01T12:00:00.000Z [ERROR]: nested message'); }); }); describe('getLogLevel', () => { it('should return current log level', () => { expect(logger.getLogLevel()).toBe('info'); }); }); describe('setLogLevel', () => { it('should set valid log levels', async () => { logger.setLogLevel('debug'); expect(mockLogger.transports[0].level).toBe('debug'); logger.setLogLevel('info'); expect(mockLogger.transports[0].level).toBe('info'); }); it('should throw error for invalid log level', () => { expect(() => logger.setLogLevel('invalid' as any)).toThrow('Invalid log level: invalid'); }); }); describe('initializeRunLogging', () => { let cliState: { debugLogFile?: string; errorLogFile?: string }; let winston: any; let expectedDebugFile: string; let expectedErrorFile: string; beforeEach(async () => { vi.useFakeTimers(); vi.setSystemTime(new Date('2025-03-01T12:00:00.000Z')); expectedDebugFile = path.join( '/mock/config', 'logs', 'promptfoo-debug-2025-03-01_12-00-00-000Z.log', ); expectedErrorFile = path.join( '/mock/config', 'logs', 'promptfoo-error-2025-03-01_12-00-00-000Z.log', ); cliState = (await import('../src/cliState')).default; winston = await import('winston'); }); afterEach(() => { vi.useRealTimers(); }); it('should create debug and error log files when enabled', () => { (fsMock.existsSync as Mock).mockReturnValue(false); (fsMock.readdirSync as Mock).mockReturnValue([]); logger.initializeRunLogging(); expect(mockGetConfigDirectoryPath).toHaveBeenCalledWith(true); expect(fsMock.mkdirSync).toHaveBeenCalledWith(path.join('/mock/config', 'logs'), { recursive: true, }); expect(cliState.debugLogFile).toBe(expectedDebugFile); expect(cliState.errorLogFile).toBe(expectedErrorFile); const debugCall = vi .mocked(winston.default.transports.File) .mock.calls.find(([config]: any[]) => config.level === 'debug'); const errorCall = vi .mocked(winston.default.transports.File) .mock.calls.find(([config]: any[]) => config.level === 'error'); expect(debugCall?.[0]).toEqual( expect.objectContaining({ level: 'debug', filename: cliState.debugLogFile, }), ); expect(errorCall?.[0]).toEqual( expect.objectContaining({ level: 'error', filename: cliState.errorLogFile, }), ); expect(mockLogger.add).toHaveBeenCalledTimes(2); expect(winston.default.transports.File).toHaveBeenCalledTimes(2); }); it('should respect PROMPTFOO_DISABLE_DEBUG_LOG', () => { mockGetEnvBool.mockImplementation((key, defaultValue) => key === 'PROMPTFOO_DISABLE_DEBUG_LOG' ? true : defaultValue, ); (fsMock.existsSync as Mock).mockReturnValue(false); logger.initializeRunLogging(); expect(cliState.debugLogFile).toBeUndefined(); expect(cliState.errorLogFile).toBe(expectedErrorFile); expect(winston.default.transports.File).toHaveBeenCalledTimes(1); const errorConfig = vi.mocked(winston.default.transports.File).mock.calls[0][0]; expect(errorConfig.level).toBe('error'); expect(mockLogger.add).toHaveBeenCalledTimes(1); }); it('should respect PROMPTFOO_DISABLE_ERROR_LOG', () => { mockGetEnvBool.mockImplementation((key, defaultValue) => key === 'PROMPTFOO_DISABLE_ERROR_LOG' ? true : defaultValue, ); (fsMock.existsSync as Mock).mockReturnValue(false); logger.initializeRunLogging(); expect(cliState.debugLogFile).toBe(expectedDebugFile); expect(cliState.errorLogFile).toBeUndefined(); expect(winston.default.transports.File).toHaveBeenCalledTimes(1); const debugConfig = vi.mocked(winston.default.transports.File).mock.calls[0][0]; expect(debugConfig.level).toBe('debug'); expect(mockLogger.add).toHaveBeenCalledTimes(1); }); it('should warn when creating file transports fails', () => { (fsMock.existsSync as Mock).mockReturnValue(false); // Use function keyword to make it constructable const throwingConstructor = function () { throw new Error('boom'); }; vi.mocked(winston.default.transports.File).mockImplementationOnce( throwingConstructor as unknown as typeof winston.default.transports.File, ); logger.initializeRunLogging(); expect(mockLogger.warn).toHaveBeenCalledWith( expect.objectContaining({ message: expect.stringContaining('Error creating run log file: Error: boom'), }), ); expect(cliState.debugLogFile).toBe(expectedDebugFile); expect(cliState.errorLogFile).toBeUndefined(); expect(mockLogger.add).not.toHaveBeenCalled(); expect(winston.default.transports.File).toHaveBeenCalledTimes(1); }); it('should respect PROMPTFOO_LOG_DIR environment variable', () => { const customLogDir = '/custom/log/dir'; mockGetEnvString.mockImplementation((key: string, defaultValue: any) => { if (key === 'PROMPTFOO_LOG_DIR') { return customLogDir; } return defaultValue; }); (fsMock.existsSync as Mock).mockReturnValue(false); (fsMock.readdirSync as Mock).mockReturnValue([]); logger.initializeRunLogging(); // Use path.resolve() to match the actual implementation behavior (handles Windows paths correctly) const resolvedCustomLogDir = path.resolve(customLogDir); const expectedCustomDebugFile = path.join( resolvedCustomLogDir, 'promptfoo-debug-2025-03-01_12-00-00-000Z.log', ); const expectedCustomErrorFile = path.join( resolvedCustomLogDir, 'promptfoo-error-2025-03-01_12-00-00-000Z.log', ); expect(cliState.debugLogFile).toBe(expectedCustomDebugFile); expect(cliState.errorLogFile).toBe(expectedCustomErrorFile); expect(fsMock.mkdirSync).toHaveBeenCalledWith(resolvedCustomLogDir, { recursive: true }); }); }); describe('initializeSourceMapSupport', () => { it('should only call install once across concurrent and repeated invocations', async () => { // Save and clear LOG_LEVEL to prevent auto-initialization during import const originalLogLevel = process.env.LOG_LEVEL; mockProcessEnv({ LOG_LEVEL: undefined }); try { // Reset modules and set up fresh mocks vi.resetModules(); const mockInstall = vi.fn(); vi.doMock('source-map-support', () => ({ install: mockInstall, })); const cleanLogger = await import('../src/logger'); mockInstall.mockClear(); // Concurrent explicit calls should share one in-flight initialization. await Promise.all([ cleanLogger.initializeSourceMapSupport(), cleanLogger.initializeSourceMapSupport(), ]); expect(mockInstall).toHaveBeenCalledTimes(1); // A later call should not trigger install again once initialized. mockInstall.mockClear(); await cleanLogger.initializeSourceMapSupport(); expect(mockInstall).not.toHaveBeenCalled(); } finally { // Restore LOG_LEVEL if (originalLogLevel !== undefined) { mockProcessEnv({ LOG_LEVEL: originalLogLevel }); } vi.resetModules(); } }); it('should handle errors gracefully when source-map-support fails', async () => { // Save and clear LOG_LEVEL const originalLogLevel = process.env.LOG_LEVEL; mockProcessEnv({ LOG_LEVEL: undefined }); try { vi.resetModules(); // Override the mock to throw vi.doMock('source-map-support', () => { throw new Error('Module not found'); }); const freshLogger = await import('../src/logger'); // Should not throw error - the function handles errors gracefully await expect(freshLogger.initializeSourceMapSupport()).resolves.toBeUndefined(); } finally { // Restore LOG_LEVEL if (originalLogLevel !== undefined) { mockProcessEnv({ LOG_LEVEL: originalLogLevel }); } vi.resetModules(); } }); }); describe('isDebugEnabled', () => { it('should return true when debug level is set', () => { mockLogger.transports[0].level = 'debug'; expect(logger.isDebugEnabled()).toBe(true); }); it('should return false for non-debug levels', () => { mockLogger.transports[0].level = 'info'; expect(logger.isDebugEnabled()).toBe(false); }); }); describe('logger methods with empty strings', () => { it('should correctly log empty strings', () => { logger.default.info(''); expect(mockLogger.info).toHaveBeenCalledWith({ message: '', location: '' }); logger.default.error(''); expect(mockLogger.error).toHaveBeenCalledWith({ message: '', location: '' }); logger.default.warn(''); expect(mockLogger.warn).toHaveBeenCalledWith({ message: '', location: '' }); logger.default.debug(''); expect(mockLogger.debug).toHaveBeenCalledWith({ message: '', location: expect.any(String), }); }); }); describe('extractMessage helper', () => { it('should extract message from string message', () => { const info = { level: 'info', message: 'direct message' } as any; const result = logger.consoleFormatter(info); expect(result).toBe('direct message'); }); it('should extract message from nested object', () => { const info = { level: 'info', message: { message: 'nested message content', location: '[test:1]', }, } as any; const result = logger.consoleFormatter(info); expect(result).toBe('nested message content'); }); it('should convert non-string messages to strings', () => { const info = { level: 'info', message: 42 } as any; const result = logger.consoleFormatter(info); expect(result).toBe('42'); }); it('should convert undefined to string', () => { const info = { level: 'info', message: undefined } as any; const result = logger.consoleFormatter(info); expect(result).toBe('undefined'); }); it('should convert null to string', () => { const info = { level: 'info', message: null } as any; const result = logger.consoleFormatter(info); expect(result).toBe('null'); }); }); describe('createLogMethod', () => { it('should include location when debug level is set even for non-debug methods', () => { // Set debug level logger.setLogLevel('debug'); // Log with info level, should include location because debug is enabled logger.default.info('test info with debug enabled'); // Verify location is included in the call to the underlying logger expect(mockLogger.info).toHaveBeenCalledWith({ message: 'test info with debug enabled', location: expect.any(String), }); }); }); describe('logger instance', () => { it('should have properly bound add and remove methods', () => { // Testing line 207-208: Test that the methods are correctly bound expect(typeof logger.default.add).toBe('function'); expect(typeof logger.default.remove).toBe('function'); // Test that the methods are bound to winstonLogger const addSpy = vi.spyOn(mockLogger, 'add'); const removeSpy = vi.spyOn(mockLogger, 'remove'); const transport = { name: 'test' } as any; logger.default.add(transport); expect(addSpy).toHaveBeenCalledWith(transport); logger.default.remove(transport); expect(removeSpy).toHaveBeenCalledWith(transport); }); it('should expose transports property', () => { // Test the transports property is correctly assigned (line 207-208) expect(logger.default.transports).toBe(mockLogger.transports); // Verify we can access the transports array expect(Array.isArray(logger.default.transports)).toBe(true); }); }); describe('closeLogger', () => { // Save original transports state and restore after each test let originalTransports: any[]; beforeEach(() => { originalTransports = [...mockLogger.transports]; }); afterEach(() => { // Restore transports to original state mockLogger.transports.length = 0; mockLogger.transports.push(...originalTransports); }); it('should set shutdown flag when closing', async () => { // Create mock file transports with once/end methods for proper flush handling const createMockFileTransport = (filename: string) => { const transport = { filename, once: vi.fn((event: string, callback: () => void) => { // Immediately call the callback to simulate finish event if (event === 'finish') { setImmediate(callback); } }), on: vi.fn(), off: vi.fn(), end: vi.fn(), }; Object.setPrototypeOf(transport, winstonMock.transports.File.prototype); return transport; }; const mockFileTransport1 = createMockFileTransport('/mock/path/debug.log'); const mockFileTransport2 = createMockFileTransport('/mock/path/error.log'); // Set up transports array with file transports mockLogger.transports.length = 0; mockLogger.transports.push(mockFileTransport1 as any, mockFileTransport2 as any); // Reset shutdown flag logger.setLoggerShuttingDown(false); await logger.closeLogger(); // Shutdown flag should be set (critical for preventing writes during shutdown) expect(logger.getLoggerShuttingDown()).toBe(true); // Verify winstonLogger.end() was called to properly drain the stream pipeline // Winston's _final() internally calls transport.end() on each transport expect(mockLogger.end).toHaveBeenCalled(); expect(mockLogger.once).toHaveBeenCalledWith('finish', expect.any(Function)); // Reset for other tests logger.setLoggerShuttingDown(false); }); it('should handle file transports gracefully', async () => { const mockTransport = { filename: '/mock/path/test.log', once: vi.fn((event: string, callback: () => void) => { if (event === 'finish') { setImmediate(callback); } }), on: vi.fn(), off: vi.fn(), end: vi.fn(), }; Object.setPrototypeOf(mockTransport, winstonMock.transports.File.prototype); mockLogger.transports.length = 0; mockLogger.transports.push(mockTransport as any); // Should not throw await expect(logger.closeLogger()).resolves.not.toThrow(); // Shutdown flag should be set expect(logger.getLoggerShuttingDown()).toBe(true); // Verify winstonLogger.end() was called for proper stream draining expect(mockLogger.end).toHaveBeenCalled(); // Verify error handler was attached for "write after end" protection expect(mockTransport.on).toHaveBeenCalledWith('error', expect.any(Function)); expect(mockTransport.off).toHaveBeenCalledWith('error', expect.any(Function)); logger.setLoggerShuttingDown(false); }); it('should skip non-file transports', async () => { const mockConsoleTransport = {}; // Don't set File prototype - this is a console transport mockLogger.transports.length = 0; mockLogger.transports.push(mockConsoleTransport as any); await logger.closeLogger(); // Shutdown flag should still be set even with no file transports expect(logger.getLoggerShuttingDown()).toBe(true); logger.setLoggerShuttingDown(false); }); it('should handle errors gracefully', async () => { const mockTransport = { filename: '/mock/path/test.log', once: vi.fn((event: string, callback: () => void) => { if (event === 'finish') { setImmediate(callback); } }), on: vi.fn(), off: vi.fn(), end: vi.fn(), }; Object.setPrototypeOf(mockTransport, winstonMock.transports.File.prototype); mockLogger.transports.length = 0; mockLogger.transports.push(mockTransport as any); // Should not throw await expect(logger.closeLogger()).resolves.not.toThrow(); logger.setLoggerShuttingDown(false); }); it('should catch write after end errors during shutdown', async () => { const consoleErrorSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); let errorHandler: ((err: Error) => void) | undefined; const mockTransport = { filename: '/mock/path/test.log', once: vi.fn((event: string, callback: () => void) => { if (event === 'finish') { setImmediate(callback); } }), on: vi.fn((event: string, handler: (err: Error) => void) => { if (event === 'error') { errorHandler = handler; } }), off: vi.fn(), end: vi.fn(), }; Object.setPrototypeOf(mockTransport, winstonMock.transports.File.prototype); mockLogger.transports.length = 0; mockLogger.transports.push(mockTransport as any); const closePromise = logger.closeLogger(); // Simulate "write after end" error during shutdown if (errorHandler) { errorHandler(new Error('write after end')); } await closePromise; // The error should be silently handled, not logged to console expect(consoleErrorSpy).not.toHaveBeenCalled(); consoleErrorSpy.mockRestore(); logger.setLoggerShuttingDown(false); }); it('should handle empty transports array', async () => { mockLogger.transports.length = 0; logger.setLoggerShuttingDown(false); // Should not throw await expect(logger.closeLogger()).resolves.not.toThrow(); // Shutdown flag should still be set even with no transports expect(logger.getLoggerShuttingDown()).toBe(true); logger.setLoggerShuttingDown(false); }); it('should prevent logging after shutdown flag is set', async () => { const debugSpy = vi.spyOn(mockLogger, 'debug'); // Set shutdown flag logger.setLoggerShuttingDown(true); // Try to log using default export logger.default.debug('This should not be logged'); // Logger should not have been called (shutdown flag prevents it) expect(debugSpy).not.toHaveBeenCalled(); // Reset flag for other tests logger.setLoggerShuttingDown(false); }); }); describe('logRequestResponse', () => { let mockResponse: Partial; let consoleSpy: MockInstance; beforeEach(() => { consoleSpy = vi.spyOn(console, 'error').mockImplementation(() => {}); mockResponse = { ok: true, status: 200, statusText: 'OK', clone: vi.fn().mockReturnValue({ text: vi.fn().mockResolvedValue('{"success": true}'), }), }; }); afterEach(() => { consoleSpy.mockRestore(); vi.clearAllMocks(); }); it('should log successful requests as debug', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', response: mockResponse as Response, }); expect(mockLogger.debug).toHaveBeenCalled(); const call = mockLogger.debug.mock.calls[0][0]; expect(call.message).toContain('Api Request'); const loggedMessage = call.message; expect(loggedMessage).toContain('"message": "API request"'); expect(loggedMessage).toContain('"url": "https://api.example.com/test"'); expect(loggedMessage).toContain('"method": "POST"'); expect(loggedMessage).toContain('"status": 200'); expect(mockLogger.error).not.toHaveBeenCalled(); }); it('should log failed responses as debug when error flag not set', async () => { // @ts-expect-error mockResponse.ok = false; // @ts-expect-error mockResponse.status = 500; // @ts-expect-error mockResponse.statusText = 'Internal Server Error'; await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', response: mockResponse as Response, }); expect(mockLogger.debug).toHaveBeenCalled(); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"status": 500'); expect(loggedMessage).toContain('"statusText": "Internal Server Error"'); expect(mockLogger.error).not.toHaveBeenCalled(); }); it('should log as error when error flag is true', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', response: mockResponse as Response, error: true, }); expect(mockLogger.error).toHaveBeenCalled(); const loggedMessage = mockLogger.error.mock.calls[0][0].message; expect(loggedMessage).toContain('"url": "https://api.example.com/test"'); expect(loggedMessage).toContain('"method": "POST"'); expect(mockLogger.debug).not.toHaveBeenCalled(); }); it('should handle requests without response', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', }); expect(mockLogger.debug).toHaveBeenCalled(); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"url": "https://api.example.com/test"'); expect(loggedMessage).toContain('"method": "POST"'); expect(loggedMessage).toContain('"prompt": "test prompt"'); // Should not have status or response when no response is provided expect(loggedMessage).not.toContain('"status"'); expect(loggedMessage).not.toContain('"response"'); }); it('should sanitize sensitive data in URL and request body', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test?api_key=secret123', requestBody: { prompt: 'test prompt', api_key: 'secret456', password: 'mypassword', }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; // Check that sensitive data is redacted expect(loggedMessage).toContain('[REDACTED]'); expect(loggedMessage).toContain('"prompt": "test prompt"'); }); it('should include all request/response details in message', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt', model: 'gpt-4' }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"url": "https://api.example.com/test"'); expect(loggedMessage).toContain('"method": "POST"'); expect(loggedMessage).toContain('"prompt": "test prompt"'); expect(loggedMessage).toContain('"model": "gpt-4"'); expect(loggedMessage).toContain('"status": 200'); expect(loggedMessage).toContain('"statusText": "OK"'); // Response text is embedded as a string within the JSON expect(loggedMessage).toContain('success'); }); it('should handle response text extraction errors', async () => { mockResponse.clone = vi.fn().mockReturnValue({ text: vi.fn().mockRejectedValue(new Error('Failed to read response')), }); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"response": "Unable to read response"'); }); it('should handle complex nested request bodies', async () => { const complexBody = { messages: [ { role: 'user', content: 'Hello' }, { role: 'assistant', content: 'Hi there!' }, ], model: 'gpt-4', temperature: 0.7, max_tokens: 100, }; await logger.logRequestResponse({ url: 'https://api.example.com/chat', requestBody: complexBody, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"messages"'); expect(loggedMessage).toContain('"role": "user"'); expect(loggedMessage).toContain('"model": "gpt-4"'); }); it('should handle different HTTP methods', async () => { const methods = ['GET', 'POST', 'PUT', 'DELETE', 'PATCH']; for (const method of methods) { mockLogger.debug.mockClear(); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { data: 'test' }, requestMethod: method, response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain(`"method": "${method}"`); } }); it('should handle various HTTP status codes', async () => { const statusCodes = [ { code: 200, text: 'OK' }, { code: 201, text: 'Created' }, { code: 400, text: 'Bad Request' }, { code: 401, text: 'Unauthorized' }, { code: 403, text: 'Forbidden' }, { code: 404, text: 'Not Found' }, { code: 500, text: 'Internal Server Error' }, { code: 502, text: 'Bad Gateway' }, { code: 503, text: 'Service Unavailable' }, ]; for (const { code, text } of statusCodes) { mockLogger.debug.mockClear(); mockLogger.error.mockClear(); // @ts-expect-error mockResponse.ok = code >= 200 && code < 300; // @ts-expect-error mockResponse.status = code; // @ts-expect-error mockResponse.statusText = text; await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { data: 'test' }, requestMethod: 'POST', response: mockResponse as Response, }); // All status codes should log as debug when error flag is not set const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain(`"status": ${code}`); expect(loggedMessage).toContain(`"statusText": "${text}"`); expect(mockLogger.debug).toHaveBeenCalled(); expect(mockLogger.error).not.toHaveBeenCalled(); } }); it('should log as error when error flag is set regardless of status code', async () => { const statusCodes = [ { code: 200, text: 'OK' }, { code: 400, text: 'Bad Request' }, { code: 500, text: 'Internal Server Error' }, ]; for (const { code, text } of statusCodes) { mockLogger.debug.mockClear(); mockLogger.error.mockClear(); // @ts-expect-error mockResponse.ok = code >= 200 && code < 300; // @ts-expect-error mockResponse.status = code; // @ts-expect-error mockResponse.statusText = text; await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { data: 'test' }, requestMethod: 'POST', response: mockResponse as Response, error: true, // Explicitly set error flag }); // Should always log as error when error flag is true const loggedMessage = mockLogger.error.mock.calls[0][0].message; expect(loggedMessage).toContain(`"status": ${code}`); expect(loggedMessage).toContain(`"statusText": "${text}"`); expect(mockLogger.error).toHaveBeenCalled(); expect(mockLogger.debug).not.toHaveBeenCalled(); } }); it('should handle empty request body', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: {}, requestMethod: 'GET', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"requestBody": {}'); }); it('should handle null request body', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: null, requestMethod: 'GET', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('"requestBody": null'); }); it('should handle undefined request body', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: undefined, requestMethod: 'GET', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; // When undefined is passed through sanitizeObject, it may be omitted or converted to null // Verify the log envelope and stable serialized fields still exist without assuming requestBody shape. expect(loggedMessage).toContain('Api Request'); expect(loggedMessage).toContain('"message": "API request"'); expect(loggedMessage).toContain('"url": "https://api.example.com/test"'); }); it('should handle response with empty body', async () => { mockResponse.clone = vi.fn().mockReturnValue({ text: vi.fn().mockResolvedValue(''), }); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { data: 'test' }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; // Empty response text should not be included in the log object expect(loggedMessage).not.toContain('"response"'); }); it('should handle response with whitespace-only body', async () => { mockResponse.clone = vi.fn().mockReturnValue({ text: vi.fn().mockResolvedValue(' \n\t '), }); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { data: 'test' }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; // Whitespace-only response should be included expect(loggedMessage).toContain('"response": " \\n\\t "'); }); it('should log requests with very long URLs', async () => { const longUrl = 'https://api.example.com/test?' + 'param=value&'.repeat(100); await logger.logRequestResponse({ url: longUrl, requestBody: { data: 'test' }, requestMethod: 'GET', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('https://api.example.com/test'); }); it('should handle concurrent logging calls', async () => { const promises = Array.from({ length: 5 }, (_, i) => logger.logRequestResponse({ url: `https://api.example.com/test${i}`, requestBody: { id: i }, requestMethod: 'POST', response: mockResponse as Response, }), ); await Promise.all(promises); expect(mockLogger.debug).toHaveBeenCalledTimes(5); }); it('should maintain message format consistency', async () => { await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test' }, requestMethod: 'POST', response: mockResponse as Response, }); const loggedMessage = mockLogger.debug.mock.calls[0][0].message; expect(loggedMessage).toContain('Api Request'); expect(loggedMessage).toContain('"message": "API request"'); expect(loggedMessage).toContain('"url":'); expect(loggedMessage).toContain('"method":'); expect(loggedMessage).toContain('"requestBody":'); expect(loggedMessage).toContain('"status":'); expect(loggedMessage).toContain('"response":'); }); }); describe('setStructuredLogging with custom logger', () => { let customLogger: { debug: ReturnType; info: ReturnType; warn: ReturnType; error: ReturnType; }; beforeEach(() => { customLogger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn(), }; // Set custom logger to bypass default createLogMethod wrappers logger.setLogger(customLogger); }); afterEach(() => { // Reset to default state after each test logger.setStructuredLogging(false); }); it('should pass structured object when enabled', () => { logger.setStructuredLogging(true); logger.default.info('test message', { userId: '123', action: 'test' }); // When structured logging is enabled, custom logger receives object expect(customLogger.info).toHaveBeenCalledWith( expect.objectContaining({ message: 'test message', userId: '123', action: 'test', }), ); }); it('should pass string with appended JSON when disabled', () => { logger.setStructuredLogging(false); logger.default.info('test message', { userId: '123' }); // When structured logging is disabled, context is appended as JSON string const call = customLogger.info.mock.calls[0][0]; expect(typeof call).toBe('string'); expect(call).toContain('test message'); expect(call).toContain('"userId"'); expect(call).toContain('123'); }); it('should include all context fields in structured output', () => { logger.setStructuredLogging(true); const context = { userId: 'user-123', requestId: 'req-456', duration: 100, }; logger.default.info('operation completed', context); expect(customLogger.info).toHaveBeenCalledWith( expect.objectContaining({ message: 'operation completed', userId: 'user-123', requestId: 'req-456', duration: 100, }), ); }); it('should pass plain string when no context provided', () => { logger.setStructuredLogging(true); logger.default.info('simple message'); // Without context, just pass the string regardless of structured logging setting expect(customLogger.info).toHaveBeenCalledWith('simple message'); }); }); describe('setLogger', () => { let customLogger: { debug: ReturnType; info: ReturnType; warn: ReturnType; error: ReturnType; }; beforeEach(() => { customLogger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn(), }; }); afterEach(() => { // Reset structured logging logger.setStructuredLogging(false); }); it('should route logs through custom logger', () => { logger.setLogger(customLogger); logger.default.info('test message'); expect(customLogger.info).toHaveBeenCalledWith('test message'); }); it('should pass structured objects to custom logger when structured logging enabled', () => { logger.setLogger(customLogger); logger.setStructuredLogging(true); logger.default.info('test message', { requestId: 'req-123' }); expect(customLogger.info).toHaveBeenCalledWith( expect.objectContaining({ message: 'test message', requestId: 'req-123', }), ); }); it('should validate custom logger has required methods', () => { expect(() => logger.setLogger(null as any)).toThrow( 'Custom logger must be a valid object with required logging methods', ); expect(() => logger.setLogger({} as any)).toThrow( 'Custom logger is missing required methods', ); expect(() => logger.setLogger({ info: vi.fn() } as any)).toThrow( 'Custom logger is missing required methods: debug, warn, error', ); }); it('should work with winston-style loggers that accept objects', () => { // Simulate a winston-style logger that handles object arguments const winstonStyleLogger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn(), }; logger.setLogger(winstonStyleLogger); logger.setStructuredLogging(true); logger.default.info('structured log', { key: 'value' }); expect(winstonStyleLogger.info).toHaveBeenCalledWith({ message: 'structured log', key: 'value', }); }); }); describe('logRequestResponse with structured logging', () => { let mockResponse: Partial; let customLogger: { debug: ReturnType; info: ReturnType; warn: ReturnType; error: ReturnType; }; beforeEach(() => { mockResponse = { ok: true, status: 200, statusText: 'OK', clone: vi.fn().mockReturnValue({ text: vi.fn().mockResolvedValue('{"success": true}'), }), }; customLogger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn(), }; // Set custom logger to test structured logging behavior logger.setLogger(customLogger); }); afterEach(() => { logger.setStructuredLogging(false); }); it('should pass structured object with all request details', async () => { logger.setStructuredLogging(true); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: { prompt: 'test prompt' }, requestMethod: 'POST', response: mockResponse as Response, }); expect(customLogger.debug).toHaveBeenCalledWith( expect.objectContaining({ message: 'API request', url: 'https://api.example.com/test', method: 'POST', status: 200, statusText: 'OK', }), ); }); it('should include response text in structured output', async () => { logger.setStructuredLogging(true); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: null, requestMethod: 'GET', response: mockResponse as Response, }); const callArg = customLogger.debug.mock.calls[0][0]; // Response text comes from the mock - exact format depends on mock implementation expect(callArg).toHaveProperty('response'); expect(callArg.response).toContain('success'); }); it('should use error level when error flag is set', async () => { logger.setStructuredLogging(true); await logger.logRequestResponse({ url: 'https://api.example.com/test', requestBody: null, requestMethod: 'GET', response: mockResponse as Response, error: true, }); expect(customLogger.error).toHaveBeenCalled(); expect(customLogger.debug).not.toHaveBeenCalled(); }); it('should sanitize sensitive data in structured output', async () => { logger.setStructuredLogging(true); await logger.logRequestResponse({ url: 'https://api.example.com/test?api_key=secret123', requestBody: { password: 'secret', data: 'safe' }, requestMethod: 'POST', response: mockResponse as Response, }); const callArg = customLogger.debug.mock.calls[0][0]; // URL should have sensitive params redacted (may be URL-encoded as %5BREDACTED%5D) expect(callArg.url).toMatch(/(\[REDACTED\]|%5BREDACTED%5D)/); // Request body should have sensitive fields redacted expect(JSON.stringify(callArg.requestBody)).toContain('[REDACTED]'); }); }); });