diff --git a/packages/core/src/server-runtime-client.ts b/packages/core/src/server-runtime-client.ts index c63ddbe22e41..e10438ea6efc 100644 --- a/packages/core/src/server-runtime-client.ts +++ b/packages/core/src/server-runtime-client.ts @@ -36,6 +36,7 @@ export class ServerRuntimeClient< > extends Client { private _logFlushIdleTimeout: ReturnType | undefined; private _logWeight: number; + private _isLogTimerActive: boolean; /** * Creates a new Edge SDK instance. @@ -48,6 +49,7 @@ export class ServerRuntimeClient< super(options); this._logWeight = 0; + this._isLogTimerActive = false; // eslint-disable-next-line deprecation/deprecation const shouldEnableLogs = this._options.enableLogs ?? this._options._experiments?.enableLogs; @@ -58,6 +60,7 @@ export class ServerRuntimeClient< client.on('flushLogs', () => { client._logWeight = 0; clearTimeout(client._logFlushIdleTimeout); + client._isLogTimerActive = false; }); client.on('afterCaptureLog', log => { @@ -68,10 +71,15 @@ export class ServerRuntimeClient< // the payload gets too big. if (client._logWeight >= 800_000) { _INTERNAL_flushLogsBuffer(client); - } else { - // start an idle timeout to flush the logs buffer if no logs are captured for a while + } else if (!client._isLogTimerActive) { + // Only start timer if one isn't already running. + // This prevents flushing being delayed by logs that arrive close to the timeout limit + // and thus resetting the flushing timeout and delaying logs being flushed. + client._isLogTimerActive = true; client._logFlushIdleTimeout = setTimeout(() => { _INTERNAL_flushLogsBuffer(client); + // Note: _isLogTimerActive is reset by the flushLogs handler above, not here, + // to avoid race conditions when new logs arrive during the flush. }, DEFAULT_LOG_FLUSH_INTERVAL); } }); diff --git a/packages/core/test/lib/server-runtime-client.test.ts b/packages/core/test/lib/server-runtime-client.test.ts index 708ac8716070..ccb205749cf7 100644 --- a/packages/core/test/lib/server-runtime-client.test.ts +++ b/packages/core/test/lib/server-runtime-client.test.ts @@ -298,4 +298,155 @@ describe('ServerRuntimeClient', () => { expect(client['_logWeight']).toBe(0); // Weight should be reset after flush }); }); + + describe('log timeout-based flushing', () => { + it('flushes logs after idle timeout', () => { + vi.useFakeTimers(); + + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + enableLogs: true, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Add a log (starts the timer) + _INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client); + + // Should not have flushed yet + expect(sendEnvelopeSpy).not.toHaveBeenCalled(); + + // Fast forward to trigger the timeout + vi.advanceTimersByTime(5000); + + // Should have flushed + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_logWeight']).toBe(0); + + vi.useRealTimers(); + }); + + it('does not reset idle timeout when new logs are captured', () => { + vi.useFakeTimers(); + + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + enableLogs: true, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Add initial log (starts the timer) + _INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client); + + // Fast forward part of the idle timeout + vi.advanceTimersByTime(2500); + + // Add another log which should NOT reset the timeout + _INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client); + + // Fast forward the remaining time to reach the full timeout from the first log + vi.advanceTimersByTime(2500); + + // Should have flushed both logs since timeout was not reset + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_logWeight']).toBe(0); + + vi.useRealTimers(); + }); + + it('starts new timer after timeout completes and flushes', () => { + vi.useFakeTimers(); + + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + enableLogs: true, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // First batch: Add a log and let it flush + _INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client); + + // Fast forward to trigger the first flush + vi.advanceTimersByTime(5000); + + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + + // Second batch: Add another log after the first flush completed + _INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client); + + // Should not have flushed yet + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + + // Fast forward to trigger the second flush + vi.advanceTimersByTime(5000); + + // Should have flushed the second log + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(2); + + vi.useRealTimers(); + }); + + it('does not start multiple timers for continuous logs', () => { + vi.useFakeTimers(); + + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + enableLogs: true, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Add multiple logs in quick succession + _INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client); + _INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client); + _INTERNAL_captureLog({ message: 'test log 3', level: 'info' }, client); + + // _isLogTimerActive should be true (only one timer running) + expect(client['_isLogTimerActive']).toBe(true); + + // Fast forward to trigger the timeout + vi.advanceTimersByTime(5000); + + // Should have flushed all logs together + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_logWeight']).toBe(0); + expect(client['_isLogTimerActive']).toBe(false); + + vi.useRealTimers(); + }); + + it('clears timer and flag when weight threshold is exceeded', () => { + vi.useFakeTimers(); + + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + enableLogs: true, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Add a small log that starts the timer + _INTERNAL_captureLog({ message: 'small log', level: 'info' }, client); + + expect(client['_isLogTimerActive']).toBe(true); + + // Add a large log that exceeds the weight threshold + const largeMessage = 'x'.repeat(400_000); // 400KB string + _INTERNAL_captureLog({ message: largeMessage, level: 'info' }, client); + + // Should have flushed due to weight, and timer flag should be reset + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_isLogTimerActive']).toBe(false); + expect(client['_logWeight']).toBe(0); + + vi.useRealTimers(); + }); + }); });