Skip to content

Commit b77c631

Browse files
committed
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
1 parent 86e6457 commit b77c631

File tree

2 files changed

+161
-2
lines changed

2 files changed

+161
-2
lines changed

packages/core/src/server-runtime-client.ts

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@ export class ServerRuntimeClient<
3636
> extends Client<O> {
3737
private _logFlushIdleTimeout: ReturnType<typeof setTimeout> | undefined;
3838
private _logWeight: number;
39+
private _isLogTimerActive: boolean;
3940

4041
/**
4142
* Creates a new Edge SDK instance.
@@ -48,6 +49,7 @@ export class ServerRuntimeClient<
4849
super(options);
4950

5051
this._logWeight = 0;
52+
this._isLogTimerActive = false;
5153

5254
// eslint-disable-next-line deprecation/deprecation
5355
const shouldEnableLogs = this._options.enableLogs ?? this._options._experiments?.enableLogs;
@@ -58,6 +60,7 @@ export class ServerRuntimeClient<
5860
client.on('flushLogs', () => {
5961
client._logWeight = 0;
6062
clearTimeout(client._logFlushIdleTimeout);
63+
client._isLogTimerActive = false;
6164
});
6265

6366
client.on('afterCaptureLog', log => {
@@ -68,10 +71,15 @@ export class ServerRuntimeClient<
6871
// the payload gets too big.
6972
if (client._logWeight >= 800_000) {
7073
_INTERNAL_flushLogsBuffer(client);
71-
} else {
72-
// start an idle timeout to flush the logs buffer if no logs are captured for a while
74+
} else if (!client._isLogTimerActive) {
75+
// Only start timer if one isn't already running.
76+
// This prevents flushing being delayed by logs that arrive close to the timeout limit
77+
// and thus resetting the flushing timeout and delaying logs being flushed.
78+
client._isLogTimerActive = true;
7379
client._logFlushIdleTimeout = setTimeout(() => {
7480
_INTERNAL_flushLogsBuffer(client);
81+
// Note: _isLogTimerActive is reset by the flushLogs handler above, not here,
82+
// to avoid race conditions when new logs arrive during the flush.
7583
}, DEFAULT_LOG_FLUSH_INTERVAL);
7684
}
7785
});

packages/core/test/lib/server-runtime-client.test.ts

Lines changed: 151 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -298,4 +298,155 @@ describe('ServerRuntimeClient', () => {
298298
expect(client['_logWeight']).toBe(0); // Weight should be reset after flush
299299
});
300300
});
301+
302+
describe('log timeout-based flushing', () => {
303+
it('flushes logs after idle timeout', () => {
304+
vi.useFakeTimers();
305+
306+
const options = getDefaultClientOptions({
307+
dsn: PUBLIC_DSN,
308+
enableLogs: true,
309+
});
310+
client = new ServerRuntimeClient(options);
311+
312+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
313+
314+
// Add a log (starts the timer)
315+
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client);
316+
317+
// Should not have flushed yet
318+
expect(sendEnvelopeSpy).not.toHaveBeenCalled();
319+
320+
// Fast forward to trigger the timeout
321+
vi.advanceTimersByTime(5000);
322+
323+
// Should have flushed
324+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
325+
expect(client['_logWeight']).toBe(0);
326+
327+
vi.useRealTimers();
328+
});
329+
330+
it('does not reset idle timeout when new logs are captured', () => {
331+
vi.useFakeTimers();
332+
333+
const options = getDefaultClientOptions({
334+
dsn: PUBLIC_DSN,
335+
enableLogs: true,
336+
});
337+
client = new ServerRuntimeClient(options);
338+
339+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
340+
341+
// Add initial log (starts the timer)
342+
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client);
343+
344+
// Fast forward part of the idle timeout
345+
vi.advanceTimersByTime(2500);
346+
347+
// Add another log which should NOT reset the timeout
348+
_INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client);
349+
350+
// Fast forward the remaining time to reach the full timeout from the first log
351+
vi.advanceTimersByTime(2500);
352+
353+
// Should have flushed both logs since timeout was not reset
354+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
355+
expect(client['_logWeight']).toBe(0);
356+
357+
vi.useRealTimers();
358+
});
359+
360+
it('starts new timer after timeout completes and flushes', () => {
361+
vi.useFakeTimers();
362+
363+
const options = getDefaultClientOptions({
364+
dsn: PUBLIC_DSN,
365+
enableLogs: true,
366+
});
367+
client = new ServerRuntimeClient(options);
368+
369+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
370+
371+
// First batch: Add a log and let it flush
372+
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client);
373+
374+
// Fast forward to trigger the first flush
375+
vi.advanceTimersByTime(5000);
376+
377+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
378+
379+
// Second batch: Add another log after the first flush completed
380+
_INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client);
381+
382+
// Should not have flushed yet
383+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
384+
385+
// Fast forward to trigger the second flush
386+
vi.advanceTimersByTime(5000);
387+
388+
// Should have flushed the second log
389+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(2);
390+
391+
vi.useRealTimers();
392+
});
393+
394+
it('does not start multiple timers for continuous logs', () => {
395+
vi.useFakeTimers();
396+
397+
const options = getDefaultClientOptions({
398+
dsn: PUBLIC_DSN,
399+
enableLogs: true,
400+
});
401+
client = new ServerRuntimeClient(options);
402+
403+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
404+
405+
// Add multiple logs in quick succession
406+
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, client);
407+
_INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, client);
408+
_INTERNAL_captureLog({ message: 'test log 3', level: 'info' }, client);
409+
410+
// _isLogTimerActive should be true (only one timer running)
411+
expect(client['_isLogTimerActive']).toBe(true);
412+
413+
// Fast forward to trigger the timeout
414+
vi.advanceTimersByTime(5000);
415+
416+
// Should have flushed all logs together
417+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
418+
expect(client['_logWeight']).toBe(0);
419+
expect(client['_isLogTimerActive']).toBe(false);
420+
421+
vi.useRealTimers();
422+
});
423+
424+
it('clears timer and flag when weight threshold is exceeded', () => {
425+
vi.useFakeTimers();
426+
427+
const options = getDefaultClientOptions({
428+
dsn: PUBLIC_DSN,
429+
enableLogs: true,
430+
});
431+
client = new ServerRuntimeClient(options);
432+
433+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
434+
435+
// Add a small log that starts the timer
436+
_INTERNAL_captureLog({ message: 'small log', level: 'info' }, client);
437+
438+
expect(client['_isLogTimerActive']).toBe(true);
439+
440+
// Add a large log that exceeds the weight threshold
441+
const largeMessage = 'x'.repeat(400_000); // 400KB string
442+
_INTERNAL_captureLog({ message: largeMessage, level: 'info' }, client);
443+
444+
// Should have flushed due to weight, and timer flag should be reset
445+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
446+
expect(client['_isLogTimerActive']).toBe(false);
447+
expect(client['_logWeight']).toBe(0);
448+
449+
vi.useRealTimers();
450+
});
451+
});
301452
});

0 commit comments

Comments
 (0)