From 44be7671a8af0b06e4d81c628614f4cefe851f0b Mon Sep 17 00:00:00 2001 From: Andrei Borza Date: Fri, 14 Nov 2025 20:29:59 +0100 Subject: [PATCH] fix(v9/core): Fix logs flush timeout starvation with continuous logging The flush timeout was being reset on every incoming log, preventing flushes when logs arrived continuously. Now, the timer starts on the first log won't get reset, ensuring logs flush within the configured interval. Backport of: #18211 --- packages/core/src/server-runtime-client.ts | 12 +- .../test/lib/server-runtime-client.test.ts | 151 ++++++++++++++++++ 2 files changed, 161 insertions(+), 2 deletions(-) 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(); + }); + }); });