-
Notifications
You must be signed in to change notification settings - Fork 61
fix(debug): buffer pre-init events and flush to real logger on init #448
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 1 commit
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,32 +1,106 @@ | ||||||
| import { BrowserWindow } from 'electron'; | ||||||
| import type { DebugEvent } from '@clawwork/shared'; | ||||||
| import type { DebugEvent, LogEventInput } from '@clawwork/shared'; | ||||||
| import type { DebugLogger } from './logger.js'; | ||||||
| import { createDebugLogger } from './logger.js'; | ||||||
|
|
||||||
| const noop = (): DebugEvent => ({ ts: '', level: 'debug', domain: 'app', event: '' }) as DebugEvent; | ||||||
| let debugLogger: DebugLogger = { | ||||||
| debug: noop, | ||||||
| info: noop, | ||||||
| warn: noop, | ||||||
| error: noop, | ||||||
| log: noop, | ||||||
| getRecentEvents: () => [], | ||||||
| currentFilePath: () => '', | ||||||
| }; | ||||||
| const MAX_PRE_INIT_BUFFER = 256; | ||||||
|
|
||||||
| let debugLogger: DebugLogger; | ||||||
| let isInitialized = false; | ||||||
|
|
||||||
| function createNoopLogger(): DebugLogger { | ||||||
| const preInitBuffer: DebugEvent[] = []; | ||||||
|
|
||||||
| const flushToLogger = (logger: DebugLogger): void => { | ||||||
| for (const event of preInitBuffer) { | ||||||
| logger.log({ ...event, level: event.level as LogEventInput['level'] }); | ||||||
|
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 cast and object spreading are redundant here.
Suggested change
|
||||||
| } | ||||||
| preInitBuffer.length = 0; | ||||||
| }; | ||||||
|
|
||||||
| const makeBufferedLog = | ||||||
| (level: 'debug' | 'info' | 'warn' | 'error') => | ||||||
| (input: LogEventInput): DebugEvent => { | ||||||
| const event: DebugEvent = { | ||||||
| ts: new Date().toISOString(), | ||||||
| level, | ||||||
| domain: input.domain, | ||||||
| event: input.event, | ||||||
| traceId: input.traceId, | ||||||
| feature: input.feature, | ||||||
| message: input.message, | ||||||
| gatewayId: input.gatewayId, | ||||||
| sessionKey: input.sessionKey, | ||||||
| taskId: input.taskId, | ||||||
| runId: input.runId, | ||||||
| requestId: input.requestId, | ||||||
| wsFrameId: input.wsFrameId, | ||||||
| seq: input.seq, | ||||||
| attempt: input.attempt, | ||||||
| durationMs: input.durationMs, | ||||||
| ok: input.ok, | ||||||
| error: input.error, | ||||||
| data: input.data, | ||||||
| }; | ||||||
|
|
||||||
| if (preInitBuffer.length < MAX_PRE_INIT_BUFFER) { | ||||||
| preInitBuffer.push(event); | ||||||
| } | ||||||
|
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. This block can be simplified while addressing two issues:
const event = sanitizeForLog({
...input,
ts: new Date().toISOString(),
level,
} as DebugEvent);
preInitBuffer.push(event);
if (preInitBuffer.length > MAX_PRE_INIT_BUFFER) {
preInitBuffer.shift();
} |
||||||
|
|
||||||
| console.warn( | ||||||
| `[debug] Logger not initialized yet (pre-init event captured, buffer size: ${preInitBuffer.length}/${MAX_PRE_INIT_BUFFER}):`, | ||||||
| `[${level}] [${input.domain}] ${input.event}`, | ||||||
| input, | ||||||
| ); | ||||||
| return event; | ||||||
| }; | ||||||
|
|
||||||
| const noopLogger: DebugLogger = { | ||||||
| debug: makeBufferedLog('debug'), | ||||||
| info: makeBufferedLog('info'), | ||||||
| warn: makeBufferedLog('warn'), | ||||||
| error: makeBufferedLog('error'), | ||||||
| log: (input) => makeBufferedLog(input.level ?? 'debug')(input), | ||||||
| getRecentEvents: () => [...preInitBuffer], | ||||||
| currentFilePath: () => '', | ||||||
| }; | ||||||
|
|
||||||
| Object.defineProperty(noopLogger, '__flush', { | ||||||
| value: flushToLogger, | ||||||
| writable: false, | ||||||
| enumerable: false, | ||||||
| }); | ||||||
|
|
||||||
| return noopLogger; | ||||||
| } | ||||||
|
|
||||||
| debugLogger = createNoopLogger(); | ||||||
|
|
||||||
| export function initDebugLogger(debugDir: string): DebugLogger { | ||||||
| debugLogger = createDebugLogger({ | ||||||
| const realLogger = createDebugLogger({ | ||||||
| debugDir, | ||||||
| console: true, | ||||||
| onEvent: broadcastDebugEvent, | ||||||
| }); | ||||||
|
|
||||||
| const noop = debugLogger as DebugLogger & { __flush?: (logger: DebugLogger) => void }; | ||||||
| if (noop.__flush) { | ||||||
| noop.__flush(realLogger); | ||||||
| } | ||||||
|
|
||||||
| debugLogger = realLogger; | ||||||
| isInitialized = true; | ||||||
| return debugLogger; | ||||||
| } | ||||||
|
|
||||||
| export function getDebugLogger(): DebugLogger { | ||||||
| return debugLogger; | ||||||
| } | ||||||
|
|
||||||
| export function isDebugLoggerInitialized(): boolean { | ||||||
| return isInitialized; | ||||||
| } | ||||||
|
|
||||||
| function broadcastDebugEvent(event: DebugEvent): void { | ||||||
| for (const win of BrowserWindow.getAllWindows()) { | ||||||
| try { | ||||||
|
|
||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,75 @@ | ||
| import { describe, it, expect, vi, beforeEach } from 'vitest'; | ||
|
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. |
||
|
|
||
| vi.mock('electron', () => ({ | ||
| BrowserWindow: { | ||
| getAllWindows: () => [], | ||
| }, | ||
| })); | ||
|
|
||
| describe('debug logger pre-init behavior', () => { | ||
| beforeEach(async () => { | ||
| vi.resetModules(); | ||
| vi.restoreAllMocks(); | ||
| }); | ||
|
|
||
| it('buffers events before initDebugLogger runs', async () => { | ||
| const { getDebugLogger, isDebugLoggerInitialized } = await import( | ||
| '../../src/main/debug/index.js' | ||
| ); | ||
|
|
||
| const logger = getDebugLogger(); | ||
| const event1 = logger.info({ domain: 'app', event: 'test-event-1' }); | ||
| const event2 = logger.error({ domain: 'gateway', event: 'test-event-2' }); | ||
|
|
||
| expect(event1.level).toBe('info'); | ||
| expect(event1.domain).toBe('app'); | ||
| expect(event1.event).toBe('test-event-1'); | ||
| expect(event2.level).toBe('error'); | ||
| expect(event2.domain).toBe('gateway'); | ||
|
|
||
| expect(getDebugLogger().getRecentEvents()).toHaveLength(2); | ||
| expect(isDebugLoggerInitialized()).toBe(false); | ||
| }); | ||
|
|
||
| it('flushes buffered events to real logger after init', async () => { | ||
| const { getDebugLogger, initDebugLogger, isDebugLoggerInitialized } = await import( | ||
| '../../src/main/debug/index.js' | ||
| ); | ||
|
|
||
| const logger = getDebugLogger(); | ||
|
|
||
| logger.info({ domain: 'app', event: 'pre-init-event' }); | ||
| logger.warn({ domain: 'gateway', event: 'pre-init-warn' }); | ||
|
|
||
| expect(isDebugLoggerInitialized()).toBe(false); | ||
|
|
||
| const tempDir = `/tmp/test-debug-${Date.now()}`; | ||
|
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. |
||
| const realLogger = initDebugLogger(tempDir); | ||
| expect(isDebugLoggerInitialized()).toBe(true); | ||
|
|
||
| const recentEvents = realLogger.getRecentEvents(); | ||
| expect(recentEvents.some((e) => e.event === 'pre-init-event')).toBe(true); | ||
| expect(recentEvents.some((e) => e.event === 'pre-init-warn')).toBe(true); | ||
| }); | ||
|
|
||
| it('warns via console when logging before init', async () => { | ||
| const { getDebugLogger, isDebugLoggerInitialized } = await import( | ||
| '../../src/main/debug/index.js' | ||
| ); | ||
|
|
||
| if (isDebugLoggerInitialized()) { | ||
| return; | ||
| } | ||
|
|
||
| const warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {}); | ||
|
|
||
| const logger = getDebugLogger(); | ||
| logger.error({ domain: 'app', event: 'pre-init-warning-test' }); | ||
|
|
||
| expect(warnSpy).toHaveBeenCalled(); | ||
| const warningCall = warnSpy.mock.calls[0][0] as string; | ||
| expect(warningCall).toContain('[debug] Logger not initialized yet'); | ||
|
|
||
| warnSpy.mockRestore(); | ||
| }); | ||
| }); | ||
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.
Import
sanitizeForLogas a value to ensure that buffered events are properly sanitized before being stored in memory, preventing potential leakage of sensitive information.