-
Notifications
You must be signed in to change notification settings - Fork 61
fix(desktop): add size rotation and retention policy to debug logger #494
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||
|---|---|---|---|---|---|---|---|---|---|---|
| @@ -1,4 +1,14 @@ | ||||||||||
| import { createWriteStream, existsSync, mkdirSync, openSync, type WriteStream } from 'node:fs'; | ||||||||||
| import { | ||||||||||
| createWriteStream, | ||||||||||
| existsSync, | ||||||||||
| mkdirSync, | ||||||||||
| openSync, | ||||||||||
| readdirSync, | ||||||||||
| renameSync, | ||||||||||
| statSync, | ||||||||||
| unlinkSync, | ||||||||||
| type WriteStream, | ||||||||||
| } from 'node:fs'; | ||||||||||
| import { join } from 'node:path'; | ||||||||||
| import type { DebugDomain, DebugEvent, DebugLevel } from '@clawwork/shared'; | ||||||||||
| import { sanitizeForLog } from '@clawwork/shared'; | ||||||||||
|
|
@@ -8,6 +18,8 @@ interface CreateDebugLoggerOptions { | |||||||||
| maxEvents?: number; | ||||||||||
| console?: boolean; | ||||||||||
| onEvent?: (event: DebugEvent) => void; | ||||||||||
| maxFileSize?: number; | ||||||||||
| retentionDays?: number; | ||||||||||
| } | ||||||||||
|
|
||||||||||
| export interface DebugLogFilter { | ||||||||||
|
|
@@ -55,40 +67,76 @@ export interface LogEventInput { | |||||||||
| export function createDebugLogger(options: CreateDebugLoggerOptions): DebugLogger { | ||||||||||
| const maxEvents = options.maxEvents ?? 1000; | ||||||||||
| const writeConsole = options.console ?? true; | ||||||||||
| const maxFileSize = options.maxFileSize ?? 50 * 1024 * 1024; | ||||||||||
| const retentionDays = options.retentionDays ?? 14; | ||||||||||
| const recentEvents: DebugEvent[] = []; | ||||||||||
| const debugDir = options.debugDir; | ||||||||||
|
|
||||||||||
| // Write stream state — cached fd avoids open/write/close per event | ||||||||||
| let writeStream: WriteStream | null = null; | ||||||||||
| let currentLogDate = ''; | ||||||||||
| let currentFileSize = 0; | ||||||||||
|
|
||||||||||
| ensureDir(debugDir); | ||||||||||
|
|
||||||||||
| // Age-based cleanup: purge files older than retentionDays | ||||||||||
| if (retentionDays > 0) { | ||||||||||
| cleanupOldLogs(debugDir, retentionDays); | ||||||||||
| } | ||||||||||
|
|
||||||||||
| function currentFilePath(): string { | ||||||||||
| const day = new Date().toISOString().slice(0, 10); | ||||||||||
| return join(debugDir, `debug-${day}.ndjson`); | ||||||||||
| } | ||||||||||
|
|
||||||||||
| function ensureStream(): void { | ||||||||||
| /** Open a write stream for the current day's file. Restores file size via statSync | ||||||||||
| * so mid-day process restarts don't lose track of the written size. */ | ||||||||||
| function openStream(): void { | ||||||||||
| const today = new Date().toISOString().slice(0, 10); | ||||||||||
| if (writeStream && currentLogDate === today) return; | ||||||||||
|
|
||||||||||
| // Close previous day's stream | ||||||||||
| if (writeStream) { | ||||||||||
| writeStream.end(); | ||||||||||
| writeStream = null; | ||||||||||
| } | ||||||||||
|
|
||||||||||
| ensureDir(debugDir); | ||||||||||
| currentLogDate = today; | ||||||||||
| const filePath = currentFilePath(); | ||||||||||
| // Open fd synchronously so the file exists immediately and is append-only | ||||||||||
| // Restore file size on init (handles process restart mid-day) | ||||||||||
| try { | ||||||||||
| currentFileSize = statSync(filePath).size; | ||||||||||
| } catch { | ||||||||||
| currentFileSize = 0; | ||||||||||
| } | ||||||||||
| const fd = openSync(filePath, 'a'); | ||||||||||
| writeStream = createWriteStream(filePath, { fd, autoClose: true }).on('error', (err) => { | ||||||||||
| console.error('[debug] logger stream error:', err); | ||||||||||
| }); | ||||||||||
| } | ||||||||||
|
|
||||||||||
| function ensureStream(): void { | ||||||||||
| const today = new Date().toISOString().slice(0, 10); | ||||||||||
|
|
||||||||||
| // Same day, stream open — check tracked size for rotation | ||||||||||
| if (writeStream && currentLogDate === today) { | ||||||||||
| if (currentFileSize >= maxFileSize) { | ||||||||||
| // Rotate: close stream, find next slot, rename current file | ||||||||||
| writeStream.end(); | ||||||||||
| writeStream = null; | ||||||||||
|
|
||||||||||
| let rotIdx = 1; | ||||||||||
| while (existsSync(join(debugDir, `debug-${today}.${rotIdx}.ndjson`))) { | ||||||||||
| rotIdx++; | ||||||||||
| } | ||||||||||
| renameSync(currentFilePath(), join(debugDir, `debug-${today}.${rotIdx}.ndjson`)); | ||||||||||
| openStream(); | ||||||||||
| } else { | ||||||||||
| return; // stream is fine, no rotation needed | ||||||||||
| } | ||||||||||
| } else { | ||||||||||
| // Date changed, first call, or stream was rotated | ||||||||||
| if (writeStream) { | ||||||||||
| writeStream.end(); | ||||||||||
| writeStream = null; | ||||||||||
| } | ||||||||||
| openStream(); | ||||||||||
| } | ||||||||||
| } | ||||||||||
|
|
||||||||||
| function log(input: LogEventInput & { level: DebugLevel }): DebugEvent { | ||||||||||
| const event: DebugEvent = sanitizeForLog({ | ||||||||||
| ts: new Date().toISOString(), | ||||||||||
|
|
@@ -102,7 +150,9 @@ export function createDebugLogger(options: CreateDebugLoggerOptions): DebugLogge | |||||||||
|
|
||||||||||
| // Async write via persistent stream — no more blocking the event loop | ||||||||||
| ensureStream(); | ||||||||||
| writeStream!.write(`${JSON.stringify(event)}\n`, 'utf8'); | ||||||||||
| const jsonLine = `${JSON.stringify(event)}\n`; | ||||||||||
| currentFileSize += Buffer.byteLength(jsonLine, 'utf8'); | ||||||||||
| writeStream!.write(jsonLine, 'utf8'); | ||||||||||
|
|
||||||||||
| if (writeConsole) { | ||||||||||
| const line = `[${event.level}] [${event.domain}] ${event.event}`; | ||||||||||
|
|
@@ -159,3 +209,17 @@ function ensureDir(dir: string): void { | |||||||||
| mkdirSync(dir, { recursive: true }); | ||||||||||
| } | ||||||||||
| } | ||||||||||
|
|
||||||||||
| function cleanupOldLogs(dir: string, retentionDays: number): void { | ||||||||||
| const cutoff = Date.now() - retentionDays * 24 * 60 * 60 * 1000; | ||||||||||
| const entries = readdirSync(dir, { withFileTypes: true }); | ||||||||||
| for (const entry of entries) { | ||||||||||
| if (!entry.isFile()) continue; | ||||||||||
| const match = entry.name.match(/^debug-(\d{4}-\d{2}-\d{2})(?:\.\d+)?\.ndjson$/); | ||||||||||
| if (!match) continue; | ||||||||||
| const fileDate = new Date(match[1]).getTime(); | ||||||||||
| if (fileDate < cutoff) { | ||||||||||
|
Comment on lines
+220
to
+221
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Creating a new Date object for every file in the directory is inefficient. Since the log filenames use the YYYY-MM-DD format, you can perform a lexicographical string comparison instead. This is faster and avoids potential timezone edge cases during date parsing.
Suggested change
|
||||||||||
| unlinkSync(join(dir, entry.name)); | ||||||||||
| } | ||||||||||
| } | ||||||||||
| } | ||||||||||
|
Comment on lines
+213
to
+225
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The cleanupOldLogs function performs synchronous I/O operations (readdirSync, unlinkSync) on the main thread during initialization. If the log directory contains a very large number of files or if there are permission issues, this could block the Electron main process and delay app startup. It is recommended to wrap these operations in a try...catch block to prevent a minor cleanup failure from crashing the entire application. function cleanupOldLogs(dir: string, retentionDays: number): void {
try {
const cutoff = Date.now() - retentionDays * 24 * 60 * 60 * 1000;
const entries = readdirSync(dir, { withFileTypes: true });
for (const entry of entries) {
if (!entry.isFile()) continue;
const match = entry.name.match(/^debug-(\d{4}-\d{2}-\d{2})(?:\.\d+)?\.ndjson$/);
if (!match) continue;
const fileDate = new Date(match[1]).getTime();
if (fileDate < cutoff) {
try {
unlinkSync(join(dir, entry.name));
} catch (err) {
console.error("[debug] failed to delete old log " + entry.name + ":", err);
}
}
}
} catch (err) {
console.error("[debug] log cleanup failed:", err);
}
} |
||||||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,247 @@ | ||
| import { describe, expect, it, beforeEach, afterEach } from 'vitest'; | ||
| import { mkdtempSync, rmSync, existsSync, readdirSync, writeFileSync, statSync } from 'node:fs'; | ||
| import { tmpdir } from 'node:os'; | ||
| import { join } from 'node:path'; | ||
| import { createDebugLogger } from '../src/main/debug/logger'; | ||
|
|
||
| describe('debug logger size rotation', () => { | ||
| let dir: string; | ||
|
|
||
| beforeEach(() => { | ||
| dir = mkdtempSync(join(tmpdir(), 'clawwork-debug-rotation-')); | ||
| }); | ||
|
|
||
| afterEach(() => { | ||
| rmSync(dir, { recursive: true, force: true }); | ||
| }); | ||
|
|
||
| it('rotates to .1.ndjson when file exceeds maxFileSize', async () => { | ||
| const logger = createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 1000, | ||
| console: false, | ||
| maxFileSize: 100, // tiny — rotate after ~100 bytes | ||
| }); | ||
|
|
||
| // Write enough events to trigger rotation | ||
| for (let i = 0; i < 50; i++) { | ||
| logger.info({ | ||
| domain: 'gateway', | ||
| event: `test-event-${i}`, | ||
| message: 'x'.repeat(40), // each event ~60-100 bytes | ||
| }); | ||
| } | ||
|
|
||
| await logger.flush(); | ||
|
|
||
| const files = readdirSync(dir).filter((f) => f.endsWith('.ndjson')); | ||
| // Should have at least 2 files (rotated + current) | ||
| expect(files.length).toBeGreaterThanOrEqual(2); | ||
|
|
||
| // The rotated file should exist | ||
| const rotatedFiles = files.filter((f) => f.includes('.1.ndjson')); | ||
| expect(rotatedFiles.length).toBeGreaterThanOrEqual(1); | ||
|
|
||
| // The current (active) file should be under the size limit | ||
| // current is debug-YYYY-MM-DD.ndjson, rotated are .1, .2, etc. | ||
| // The "current" active file has no suffix | ||
| const activeFile = files.find((f) => /^debug-\d{4}-\d{2}-\d{2}\.ndjson$/.test(f) && !/\.\d+\.ndjson$/.test(f)); | ||
| if (activeFile) { | ||
| const size = statSync(join(dir, activeFile)).size; | ||
| expect(size).toBeLessThan(200); // well within the limit | ||
| } | ||
|
|
||
| // Verify rotated files are named correctly | ||
| for (const f of rotatedFiles) { | ||
| expect(f).toMatch(/^debug-\d{4}-\d{2}-\d{2}\.\d+\.ndjson$/); | ||
| } | ||
| }); | ||
|
|
||
| it('creates multiple rotation files .1, .2, .3 when needed', async () => { | ||
| const logger = createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 5000, | ||
| console: false, | ||
| maxFileSize: 80, // very tiny — rotate frequently | ||
| }); | ||
|
|
||
| // Write many big events to trigger multiple rotations | ||
| for (let i = 0; i < 100; i++) { | ||
| logger.info({ | ||
| domain: 'gateway', | ||
| event: `big-event-${i}`, | ||
| message: 'z'.repeat(60), | ||
| }); | ||
| } | ||
|
|
||
| await logger.flush(); | ||
|
|
||
| // Find all rotation files | ||
| const files = readdirSync(dir).filter((f) => f.endsWith('.ndjson')); | ||
| const rotNums = files | ||
| .map((f) => { | ||
| const m = f.match(/\.(\d+)\.ndjson$/); | ||
| return m ? parseInt(m[1], 10) : 0; | ||
| }) | ||
| .filter((n) => n > 0); | ||
|
|
||
| // Expect at least 2 distinct rotation indices | ||
| expect(rotNums.length).toBeGreaterThanOrEqual(2); | ||
|
|
||
| // The highest rotation index should exist | ||
| const maxRot = Math.max(...rotNums); | ||
| expect(existsSync(join(dir, `debug-${new Date().toISOString().slice(0, 10)}.${maxRot}.ndjson`))).toBe(true); | ||
| }); | ||
| }); | ||
|
|
||
| describe('debug logger retention cleanup', () => { | ||
| let dir: string; | ||
|
|
||
| beforeEach(() => { | ||
| dir = mkdtempSync(join(tmpdir(), 'clawwork-debug-retention-')); | ||
| }); | ||
|
|
||
| afterEach(() => { | ||
| rmSync(dir, { recursive: true, force: true }); | ||
| }); | ||
|
|
||
| it('deletes log files older than retentionDays on init', () => { | ||
| const today = new Date().toISOString().slice(0, 10); | ||
|
|
||
| // Create old log files (15 days ago) | ||
| const oldDate = new Date(Date.now() - 15 * 24 * 60 * 60 * 1000); | ||
| const oldDateStr = oldDate.toISOString().slice(0, 10); | ||
|
|
||
| writeFileSync(join(dir, `debug-${oldDateStr}.ndjson`), 'old log data\n'); | ||
| writeFileSync(join(dir, `debug-${oldDateStr}.1.ndjson`), 'old rotated log data\n'); | ||
|
|
||
| // Create recent log files (today) | ||
| writeFileSync(join(dir, `debug-${today}.ndjson`), 'current log data\n'); | ||
|
|
||
| // Create unrelated files that should not be touched | ||
| writeFileSync(join(dir, 'other-file.txt'), 'not a log\n'); | ||
|
|
||
| expect(existsSync(join(dir, `debug-${oldDateStr}.ndjson`))).toBe(true); | ||
| expect(existsSync(join(dir, `debug-${oldDateStr}.1.ndjson`))).toBe(true); | ||
| expect(existsSync(join(dir, `debug-${today}.ndjson`))).toBe(true); | ||
|
|
||
| // Create logger with 7-day retention — this triggers cleanup | ||
| createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 100, | ||
| console: false, | ||
| retentionDays: 7, | ||
| }); | ||
|
|
||
| // Old files should be deleted | ||
| expect(existsSync(join(dir, `debug-${oldDateStr}.ndjson`))).toBe(false); | ||
| expect(existsSync(join(dir, `debug-${oldDateStr}.1.ndjson`))).toBe(false); | ||
|
|
||
| // Recent file should remain | ||
| expect(existsSync(join(dir, `debug-${today}.ndjson`))).toBe(true); | ||
|
|
||
| // Non-log files should be untouched | ||
| expect(existsSync(join(dir, 'other-file.txt'))).toBe(true); | ||
| }); | ||
|
|
||
| it('does not delete recent files within retentionDays', () => { | ||
| const today = new Date().toISOString().slice(0, 10); | ||
|
|
||
| // Create file from 3 days ago | ||
| const recentDate = new Date(Date.now() - 3 * 24 * 60 * 60 * 1000); | ||
| const recentDateStr = recentDate.toISOString().slice(0, 10); | ||
|
|
||
| writeFileSync(join(dir, `debug-${recentDateStr}.ndjson`), 'recent log\n'); | ||
| writeFileSync(join(dir, `debug-${today}.ndjson`), 'current log\n'); | ||
|
|
||
| // Create logger with 7-day retention | ||
| createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 100, | ||
| console: false, | ||
| retentionDays: 7, | ||
| }); | ||
|
|
||
| // Both files should survive (3 days < 7 days) | ||
| expect(existsSync(join(dir, `debug-${recentDateStr}.ndjson`))).toBe(true); | ||
| expect(existsSync(join(dir, `debug-${today}.ndjson`))).toBe(true); | ||
| }); | ||
|
|
||
| it('disables cleanup when retentionDays is 0', () => { | ||
| const today = new Date().toISOString().slice(0, 10); | ||
|
|
||
| // Create very old files | ||
| const oldDate = new Date(Date.now() - 100 * 24 * 60 * 60 * 1000); | ||
| const oldDateStr = oldDate.toISOString().slice(0, 10); | ||
|
|
||
| writeFileSync(join(dir, `debug-${oldDateStr}.ndjson`), 'very old log\n'); | ||
| writeFileSync(join(dir, `debug-${today}.ndjson`), 'current log\n'); | ||
|
|
||
| // Create logger with retentionDays=0 (disabled) | ||
| createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 100, | ||
| console: false, | ||
| retentionDays: 0, | ||
| }); | ||
|
|
||
| // Old file should still exist | ||
| expect(existsSync(join(dir, `debug-${oldDateStr}.ndjson`))).toBe(true); | ||
| expect(existsSync(join(dir, `debug-${today}.ndjson`))).toBe(true); | ||
| }); | ||
| }); | ||
|
|
||
| describe('debug logger file size boundaries', () => { | ||
| let dir: string; | ||
|
|
||
| beforeEach(() => { | ||
| dir = mkdtempSync(join(tmpdir(), 'clawwork-debug-boundary-')); | ||
| }); | ||
|
|
||
| afterEach(() => { | ||
| rmSync(dir, { recursive: true, force: true }); | ||
| }); | ||
|
|
||
| it('keeps active file within size limit across rotations', async () => { | ||
| // Create a logger with a moderate size limit | ||
| const maxFileSize = 500; | ||
| const logger = createDebugLogger({ | ||
| debugDir: dir, | ||
| maxEvents: 5000, | ||
| console: false, | ||
| maxFileSize, | ||
| }); | ||
|
|
||
| // Write events in batches with flush | ||
| for (let batch = 0; batch < 5; batch++) { | ||
| for (let i = 0; i < 10; i++) { | ||
| logger.info({ | ||
| domain: 'gateway', | ||
| event: `batch-${batch}-event-${i}`, | ||
| message: 'a'.repeat(50), | ||
| }); | ||
| } | ||
| await logger.flush(); | ||
| } | ||
|
|
||
| await logger.flush(); | ||
|
|
||
| // The active file should be well within the size limit | ||
| const files = readdirSync(dir).filter((f) => f.endsWith('.ndjson')); | ||
| const activeFile = files.find((f) => /^debug-\d{4}-\d{2}-\d{2}\.ndjson$/.test(f) && !/\.\d+\.ndjson$/.test(f)); | ||
| expect(activeFile).toBeTruthy(); | ||
| const activeSize = statSync(join(dir, activeFile!)).size; | ||
|
|
||
| // Active file should not exceed maxFileSize | ||
| expect(activeSize).toBeLessThan(maxFileSize); | ||
|
|
||
| // All rotated files should also stay within limits | ||
| for (const f of files) { | ||
| if (f === activeFile) continue; | ||
| const size = statSync(join(dir, f)).size; | ||
| // Rotated files may exceed maxFileSize slightly since they're renamed when the limit is hit | ||
| // but they shouldn't be wildly larger | ||
| expect(size).toBeLessThan(maxFileSize * 2); | ||
| } | ||
| }); | ||
| }); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The writeStream.end() call is asynchronous. On Windows, calling renameSync immediately after end() will likely fail with an EBUSY or EPERM error because the file descriptor is still held open by the stream until it finishes flushing its internal buffer.
Since this is a synchronous logging flow, you should consider using fs.appendFileSync for the entire logger to simplify rotation, or you must ensure the stream is fully closed before renaming. However, WriteStream does not provide a synchronous close method. A common workaround in Electron apps for simple debug logging is to avoid WriteStream and use manual file descriptor management with fs.writeSync and fs.closeSync.