diff options
Diffstat (limited to 'packages/server/src/core/logger.test.ts')
| -rw-r--r-- | packages/server/src/core/logger.test.ts | 503 |
1 files changed, 369 insertions, 134 deletions
diff --git a/packages/server/src/core/logger.test.ts b/packages/server/src/core/logger.test.ts index 9b4f4555..2663a6be 100644 --- a/packages/server/src/core/logger.test.ts +++ b/packages/server/src/core/logger.test.ts @@ -4,194 +4,429 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; -import { Logger, MessageSenderType } from './logger.js'; +import { + describe, + it, + expect, + vi, + beforeEach, + afterEach, + afterAll, +} from 'vitest'; +import { Logger, MessageSenderType, LogEntry } from './logger.js'; +import { promises as fs } from 'node:fs'; +import path from 'node:path'; -// Mocks -const mockDb = { - exec: vi.fn((_sql, callback) => callback?.(null)), - all: vi.fn((_sql, _params, callback) => callback?.(null, [])), - run: vi.fn((_sql, _params, callback) => callback?.(null)), - close: vi.fn((callback) => callback?.(null)), -}; +const GEMINI_DIR = '.gemini'; +const LOG_FILE_NAME = 'logs.json'; +const TEST_LOG_FILE_PATH = path.join(process.cwd(), GEMINI_DIR, LOG_FILE_NAME); -vi.mock('sqlite3', () => ({ - Database: vi.fn((_dbPath, _options, callback) => { - process.nextTick(() => callback?.(null)); - return mockDb; - }), - default: { - Database: vi.fn((_dbPath, _options, callback) => { - process.nextTick(() => callback?.(null)); - return mockDb; - }), - }, -})); +async function cleanupLogFile() { + try { + await fs.unlink(TEST_LOG_FILE_PATH); + } catch (error) { + if ((error as NodeJS.ErrnoException).code !== 'ENOENT') { + // Other errors during unlink are ignored for cleanup purposes + } + } + try { + const geminiDirPath = path.join(process.cwd(), GEMINI_DIR); + const dirContents = await fs.readdir(geminiDirPath); + for (const file of dirContents) { + if (file.startsWith(LOG_FILE_NAME + '.') && file.endsWith('.bak')) { + try { + await fs.unlink(path.join(geminiDirPath, file)); + } catch (_e) { + /* ignore */ + } + } + } + } catch (error) { + if ((error as NodeJS.ErrnoException).code !== 'ENOENT') { + /* ignore if .gemini dir itself is missing */ + } + } +} + +async function readLogFile(): Promise<LogEntry[]> { + try { + const content = await fs.readFile(TEST_LOG_FILE_PATH, 'utf-8'); + return JSON.parse(content) as LogEntry[]; + } catch (error) { + if ((error as NodeJS.ErrnoException).code === 'ENOENT') { + return []; + } + throw error; + } +} describe('Logger', () => { let logger: Logger; beforeEach(async () => { - vi.resetAllMocks(); - - // Get a new instance for each test to ensure isolation, + vi.useFakeTimers(); + vi.setSystemTime(new Date('2025-01-01T12:00:00.000Z')); + await cleanupLogFile(); logger = new Logger(); - // We need to wait for the async initialize to complete - await logger.initialize().catch((err) => { - console.error('Error initializing logger:', err); - }); + // Initialize is usually called here, but some tests initialize their own instances. + // For tests that use the global `logger`, it will be initialized here. + await logger.initialize(); + }); + + afterEach(async () => { + logger.close(); + await cleanupLogFile(); + vi.useRealTimers(); + vi.resetAllMocks(); // Ensure mocks are reset for every test }); - afterEach(() => { - vi.restoreAllMocks(); - logger.close(); // Close the database connection after each test + afterAll(async () => { + await cleanupLogFile(); }); describe('initialize', () => { - it('should execute create tables if not exists', async () => { - expect(mockDb.exec).toHaveBeenCalledWith( - expect.stringMatching(/CREATE TABLE IF NOT EXISTS messages/), - expect.any(Function), - ); + it('should create .gemini directory and an empty log file if none exist', async () => { + await cleanupLogFile(); + const geminiDirPath = path.join(process.cwd(), GEMINI_DIR); + try { + await fs.rm(geminiDirPath, { recursive: true, force: true }); + } catch (_e) { + /* ignore */ + } + + const newLogger = new Logger(); + await newLogger.initialize(); + + const dirExists = await fs + .access(geminiDirPath) + .then(() => true) + .catch(() => false); + expect(dirExists).toBe(true); + const fileExists = await fs + .access(TEST_LOG_FILE_PATH) + .then(() => true) + .catch(() => false); + expect(fileExists).toBe(true); + const logContent = await readLogFile(); + expect(logContent).toEqual([]); + newLogger.close(); }); - it('should be idempotent', async () => { - mockDb.exec.mockClear(); + it('should load existing logs and set correct messageId for the current session', async () => { + const fixedTime = new Date('2025-01-01T10:00:00.000Z'); + vi.setSystemTime(fixedTime); + const currentSessionId = Math.floor(fixedTime.getTime() / 1000); + const existingLogs: LogEntry[] = [ + { + sessionId: currentSessionId, + messageId: 0, + timestamp: new Date('2025-01-01T10:00:05.000Z').toISOString(), + type: MessageSenderType.USER, + message: 'Msg1', + }, + { + sessionId: currentSessionId - 100, + messageId: 5, + timestamp: new Date('2025-01-01T09:00:00.000Z').toISOString(), + type: MessageSenderType.USER, + message: 'OldMsg', + }, + { + sessionId: currentSessionId, + messageId: 1, + timestamp: new Date('2025-01-01T10:00:10.000Z').toISOString(), + type: MessageSenderType.USER, + message: 'Msg2', + }, + ]; + await fs.mkdir(path.join(process.cwd(), GEMINI_DIR), { recursive: true }); + await fs.writeFile(TEST_LOG_FILE_PATH, JSON.stringify(existingLogs)); + const newLogger = new Logger(); + await newLogger.initialize(); + expect(newLogger['messageId']).toBe(2); + expect(newLogger['logs']).toEqual(existingLogs); + newLogger.close(); + }); - await logger.initialize(); // Second call + it('should set messageId to 0 for a new session if log file exists but has no logs for current session', async () => { + const fixedTime = new Date('2025-01-01T14:00:00.000Z'); + vi.setSystemTime(fixedTime); + const existingLogs: LogEntry[] = [ + { + sessionId: Math.floor(fixedTime.getTime() / 1000) - 500, + messageId: 5, + timestamp: new Date().toISOString(), + type: MessageSenderType.USER, + message: 'OldMsg', + }, + ]; + await fs.mkdir(path.join(process.cwd(), GEMINI_DIR), { recursive: true }); + await fs.writeFile(TEST_LOG_FILE_PATH, JSON.stringify(existingLogs)); + const newLogger = new Logger(); + await newLogger.initialize(); + expect(newLogger['messageId']).toBe(0); + newLogger.close(); + }); - expect(mockDb.exec).not.toHaveBeenCalled(); + it('should be idempotent', async () => { + // logger is initialized in beforeEach + await logger.logMessage(MessageSenderType.USER, 'test message'); + const initialMessageId = logger['messageId']; + const initialLogCount = logger['logs'].length; + await logger.initialize(); // Second call should not change state + expect(logger['messageId']).toBe(initialMessageId); + expect(logger['logs'].length).toBe(initialLogCount); + const logsFromFile = await readLogFile(); + expect(logsFromFile.length).toBe(1); }); - }); - describe('logMessage', () => { - it('should insert a message into the database', async () => { - const type = MessageSenderType.USER; - const message = 'Hello, world!'; - await logger.logMessage(type, message); - expect(mockDb.run).toHaveBeenCalledWith( - "INSERT INTO messages (session_id, message_id, type, message, timestamp) VALUES (?, ?, ?, ?, datetime('now'))", - [expect.any(Number), 0, type, message], // sessionId, messageId, type, message - expect.any(Function), + it('should handle invalid JSON in log file by backing it up and starting fresh', async () => { + await fs.mkdir(path.join(process.cwd(), GEMINI_DIR), { recursive: true }); + await fs.writeFile(TEST_LOG_FILE_PATH, 'invalid json'); + const consoleDebugSpy = vi + .spyOn(console, 'debug') + .mockImplementation(() => {}); + const newLogger = new Logger(); + await newLogger.initialize(); + expect(consoleDebugSpy).toHaveBeenCalledWith( + expect.stringContaining('Invalid JSON in log file'), + expect.any(SyntaxError), ); + const logContent = await readLogFile(); + expect(logContent).toEqual([]); + const dirContents = await fs.readdir( + path.join(process.cwd(), GEMINI_DIR), + ); + expect( + dirContents.some( + (f) => + f.startsWith(LOG_FILE_NAME + '.invalid_json') && f.endsWith('.bak'), + ), + ).toBe(true); + consoleDebugSpy.mockRestore(); + newLogger.close(); }); - it('should increment messageId for subsequent messages', async () => { - await logger.logMessage(MessageSenderType.USER, 'First message'); - expect(mockDb.run).toHaveBeenCalledWith( - expect.any(String), - [expect.any(Number), 0, MessageSenderType.USER, 'First message'], - expect.any(Function), + it('should handle non-array JSON in log file by backing it up and starting fresh', async () => { + await fs.mkdir(path.join(process.cwd(), GEMINI_DIR), { recursive: true }); + await fs.writeFile( + TEST_LOG_FILE_PATH, + JSON.stringify({ not: 'an array' }), ); - await logger.logMessage(MessageSenderType.USER, 'Second message'); - expect(mockDb.run).toHaveBeenCalledWith( - expect.any(String), - [expect.any(Number), 1, MessageSenderType.USER, 'Second message'], // messageId is now 1 - expect.any(Function), + const consoleDebugSpy = vi + .spyOn(console, 'debug') + .mockImplementation(() => {}); + const newLogger = new Logger(); + await newLogger.initialize(); + expect(consoleDebugSpy).toHaveBeenCalledWith( + `Log file at ${TEST_LOG_FILE_PATH} is not a valid JSON array. Starting with empty logs.`, ); + const logContent = await readLogFile(); + expect(logContent).toEqual([]); + const dirContents = await fs.readdir( + path.join(process.cwd(), GEMINI_DIR), + ); + expect( + dirContents.some( + (f) => + f.startsWith(LOG_FILE_NAME + '.malformed_array') && + f.endsWith('.bak'), + ), + ).toBe(true); + consoleDebugSpy.mockRestore(); + newLogger.close(); + }); + }); + + describe('logMessage', () => { + it('should append a message to the log file and update in-memory logs', async () => { + await logger.logMessage(MessageSenderType.USER, 'Hello, world!'); + const logsFromFile = await readLogFile(); + expect(logsFromFile.length).toBe(1); + expect(logsFromFile[0]).toMatchObject({ + sessionId: logger['sessionId'], + messageId: 0, + type: MessageSenderType.USER, + message: 'Hello, world!', + timestamp: new Date('2025-01-01T12:00:00.000Z').toISOString(), + }); + expect(logger['logs'].length).toBe(1); + expect(logger['logs'][0]).toEqual(logsFromFile[0]); + expect(logger['messageId']).toBe(1); + }); + + it('should correctly increment messageId for subsequent messages in the same session', async () => { + await logger.logMessage(MessageSenderType.USER, 'First'); + vi.advanceTimersByTime(1000); + await logger.logMessage(MessageSenderType.USER, 'Second'); + const logs = await readLogFile(); + expect(logs.length).toBe(2); + expect(logs[0].messageId).toBe(0); + expect(logs[1].messageId).toBe(1); + expect(logs[1].timestamp).not.toBe(logs[0].timestamp); + expect(logger['messageId']).toBe(2); }); - it('should handle database not initialized', async () => { + it('should handle logger not initialized', async () => { const uninitializedLogger = new Logger(); - // uninitializedLogger.initialize() is not called - const consoleErrorSpy = vi - .spyOn(console, 'error') + const consoleDebugSpy = vi + .spyOn(console, 'debug') .mockImplementation(() => {}); - await uninitializedLogger.logMessage(MessageSenderType.USER, 'test'); - - expect(consoleErrorSpy).toHaveBeenCalledWith('Database not initialized.'); - expect(mockDb.run).not.toHaveBeenCalled(); - consoleErrorSpy.mockRestore(); + expect(consoleDebugSpy).toHaveBeenCalledWith( + 'Logger not initialized or session ID missing. Cannot log message.', + ); + expect((await readLogFile()).length).toBe(0); + consoleDebugSpy.mockRestore(); + uninitializedLogger.close(); }); - it('should handle error during db.run', async () => { - const error = new Error('db.run failed'); - mockDb.run.mockImplementationOnce( - // eslint-disable-next-line @typescript-eslint/no-explicit-any - (_sql: any, _params: any, callback: any) => callback?.(error), - ); + it('should simulate concurrent writes from different logger instances to the same file', async () => { + const logger1 = new Logger(); // logger1 + vi.setSystemTime(new Date('2025-01-01T13:00:00.000Z')); + await logger1.initialize(); + const s1 = logger1['sessionId']; - await expect( - logger.logMessage(MessageSenderType.USER, 'test'), - ).rejects.toThrow('db.run failed'); - }); - }); + const logger2 = new Logger(); // logger2, will share same session if time is same + vi.setSystemTime(new Date('2025-01-01T13:00:00.000Z')); + await logger2.initialize(); + expect(logger2['sessionId']).toEqual(s1); - describe('getPreviousUserMessages', () => { - it('should query the database for messages', async () => { - mockDb.all.mockImplementationOnce( - // eslint-disable-next-line @typescript-eslint/no-explicit-any - (_sql: any, params: any, callback: any) => - callback?.(null, [{ message: 'msg1' }, { message: 'msg2' }]), - ); + // Log from logger1 + await logger1.logMessage(MessageSenderType.USER, 'L1M1'); // L1 internal msgId becomes 1, writes {s1, 0} + vi.advanceTimersByTime(10); - const messages = await logger.getPreviousUserMessages(); + // Log from logger2. It reads file (sees {s1,0}), its internal msgId for s1 is 1. + await logger2.logMessage(MessageSenderType.USER, 'L2M1'); // L2 internal msgId becomes 2, writes {s1, 1} + vi.advanceTimersByTime(10); - expect(mockDb.all).toHaveBeenCalledWith( - expect.stringMatching(/SELECT message FROM messages/), - [], - expect.any(Function), - ); - expect(messages).toEqual(['msg1', 'msg2']); + // Log from logger1. It reads file (sees {s1,0}, {s1,1}), its internal msgId for s1 is 2. + await logger1.logMessage(MessageSenderType.USER, 'L1M2'); // L1 internal msgId becomes 3, writes {s1, 2} + vi.advanceTimersByTime(10); + + // Log from logger2. It reads file (sees {s1,0}, {s1,1}, {s1,2}), its internal msgId for s1 is 3. + await logger2.logMessage(MessageSenderType.USER, 'L2M2'); // L2 internal msgId becomes 4, writes {s1, 3} + + const logsFromFile = await readLogFile(); + expect(logsFromFile.length).toBe(4); + const messageIdsInFile = logsFromFile + .map((log) => log.messageId) + .sort((a, b) => a - b); + expect(messageIdsInFile).toEqual([0, 1, 2, 3]); + + const messagesInFile = logsFromFile + .sort((a, b) => a.messageId - b.messageId) + .map((l) => l.message); + expect(messagesInFile).toEqual(['L1M1', 'L2M1', 'L1M2', 'L2M2']); + + // Check internal state (next messageId each logger would use for that session) + expect(logger1['messageId']).toBe(3); // L1 wrote 0, then 2. Next is 3. + expect(logger2['messageId']).toBe(4); // L2 wrote 1, then 3. Next is 4. + + logger1.close(); + logger2.close(); }); - it('should handle database not initialized', async () => { - const uninitializedLogger = new Logger(); - // uninitializedLogger.initialize() is not called - const consoleErrorSpy = vi - .spyOn(console, 'error') + it('should not throw, not increment messageId, and log error if writing to file fails', async () => { + const writeFileSpy = vi + .spyOn(fs, 'writeFile') + .mockRejectedValueOnce(new Error('Disk full')); + const consoleDebugSpy = vi + .spyOn(console, 'debug') .mockImplementation(() => {}); + const initialMessageId = logger['messageId']; + const initialLogCount = logger['logs'].length; - const messages = await uninitializedLogger.getPreviousUserMessages(); + await logger.logMessage(MessageSenderType.USER, 'test fail write'); - expect(consoleErrorSpy).toHaveBeenCalledWith('Database not initialized.'); - expect(messages).toEqual([]); - expect(mockDb.all).not.toHaveBeenCalled(); - consoleErrorSpy.mockRestore(); + expect(consoleDebugSpy).toHaveBeenCalledWith( + 'Error writing to log file:', + expect.any(Error), + ); + expect(logger['messageId']).toBe(initialMessageId); // Not incremented + expect(logger['logs'].length).toBe(initialLogCount); // Log not added to in-memory cache + + writeFileSpy.mockRestore(); + consoleDebugSpy.mockRestore(); }); + }); - it('should handle error during db.all', async () => { - const error = new Error('db.all failed'); - mockDb.all.mockImplementationOnce( - // eslint-disable-next-line @typescript-eslint/no-explicit-any - (_sql: any, _params: any, callback: any) => callback?.(error, []), - ); + describe('getPreviousUserMessages', () => { + it('should retrieve user messages, sorted newest first by session, then timestamp, then messageId', async () => { + const loggerSort = new Logger(); + vi.setSystemTime(new Date('2025-01-01T10:00:00.000Z')); + await loggerSort.initialize(); + const s1 = loggerSort['sessionId']!; + await loggerSort.logMessage(MessageSenderType.USER, 'S1M0_ts100000'); // msgId 0 + vi.advanceTimersByTime(10); + await loggerSort.logMessage(MessageSenderType.USER, 'S1M1_ts100010'); // msgId 1 + loggerSort.close(); // Close to ensure next initialize starts a new session if time changed - await expect(logger.getPreviousUserMessages()).rejects.toThrow( - 'db.all failed', + vi.setSystemTime(new Date('2025-01-01T11:00:00.000Z')); + await loggerSort.initialize(); // Re-initialize for a new session + const s2 = loggerSort['sessionId']!; + expect(s2).not.toEqual(s1); + await loggerSort.logMessage(MessageSenderType.USER, 'S2M0_ts110000'); // msgId 0 for s2 + vi.advanceTimersByTime(10); + await loggerSort.logMessage( + 'model' as MessageSenderType, + 'S2_Model_ts110010', ); + vi.advanceTimersByTime(10); + await loggerSort.logMessage(MessageSenderType.USER, 'S2M1_ts110020'); // msgId 1 for s2 + loggerSort.close(); + + // To test the sorting thoroughly, especially the session part, we'll read the file + // as if it was written by multiple sessions and then initialize a new logger to load them. + const combinedLogs = await readLogFile(); + const finalLogger = new Logger(); + // Manually set its internal logs to simulate loading from a file with mixed sessions + finalLogger['logs'] = combinedLogs; + finalLogger['initialized'] = true; // Mark as initialized to allow getPreviousUserMessages to run + + const messages = await finalLogger.getPreviousUserMessages(); + expect(messages).toEqual([ + 'S2M1_ts110020', + 'S2M0_ts110000', + 'S1M1_ts100010', + 'S1M0_ts100000', + ]); + finalLogger.close(); }); - }); - describe('close', () => { - it('should close the database connection', () => { - logger.close(); - expect(mockDb.close).toHaveBeenCalled(); + it('should return empty array if no user messages exist', async () => { + await logger.logMessage('system' as MessageSenderType, 'System boot'); + const messages = await logger.getPreviousUserMessages(); + expect(messages).toEqual([]); }); - it('should handle database not initialized', () => { + it('should return empty array if logger not initialized', async () => { const uninitializedLogger = new Logger(); - // uninitializedLogger.initialize() is not called + const messages = await uninitializedLogger.getPreviousUserMessages(); + expect(messages).toEqual([]); uninitializedLogger.close(); - expect(() => uninitializedLogger.close()).not.toThrow(); }); + }); - it('should handle error during db.close', () => { - const error = new Error('db.close failed'); - mockDb.close.mockImplementationOnce((callback: (error: Error) => void) => - callback?.(error), - ); - const consoleErrorSpy = vi - .spyOn(console, 'error') - .mockImplementation(() => {}); - + describe('close', () => { + it('should reset logger state', async () => { + await logger.logMessage(MessageSenderType.USER, 'A message'); logger.close(); - expect(consoleErrorSpy).toHaveBeenCalledWith( - 'Error closing database:', - error.message, + const consoleDebugSpy = vi + .spyOn(console, 'debug') + .mockImplementation(() => {}); + await logger.logMessage(MessageSenderType.USER, 'Another message'); + expect(consoleDebugSpy).toHaveBeenCalledWith( + 'Logger not initialized or session ID missing. Cannot log message.', ); - consoleErrorSpy.mockRestore(); + const messages = await logger.getPreviousUserMessages(); + expect(messages).toEqual([]); + expect(logger['initialized']).toBe(false); + expect(logger['logFilePath']).toBeUndefined(); + expect(logger['logs']).toEqual([]); + expect(logger['sessionId']).toBeUndefined(); + expect(logger['messageId']).toBe(0); + consoleDebugSpy.mockRestore(); }); }); }); |