Skip to content

Commit ad0ce51

Browse files
authored
fix(core): Fix logs and metrics flush timeout starvation with continuous logging (#18211)
The flush timeout was being reset on every incoming log, preventing flushes when logs arrived continuously. Now, the timer starts on the first log and won't get reset, ensuring logs flush within the configured interval. Fixes #18204, getsentry/sentry-react-native#5378 v9 backport: #18214
1 parent 84ef78b commit ad0ce51

File tree

2 files changed

+44
-11
lines changed

2 files changed

+44
-11
lines changed

packages/core/src/client.ts

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -94,7 +94,7 @@ function _isDoNotSendEventError(error: unknown): error is DoNotSendEventError {
9494
* This helper function encapsulates the common pattern of:
9595
* 1. Tracking accumulated weight of items
9696
* 2. Flushing when weight exceeds threshold (800KB)
97-
* 3. Flushing after idle timeout if no new items arrive
97+
* 3. Flushing after timeout period from the first item
9898
*
9999
* Uses closure variables to track weight and timeout state.
100100
*/
@@ -112,11 +112,13 @@ function setupWeightBasedFlushing<
112112
// Track weight and timeout in closure variables
113113
let weight = 0;
114114
let flushTimeout: ReturnType<typeof setTimeout> | undefined;
115+
let isTimerActive = false;
115116

116117
// @ts-expect-error - TypeScript can't narrow generic hook types to match specific overloads, but we know this is type-safe
117118
client.on(flushHook, () => {
118119
weight = 0;
119120
clearTimeout(flushTimeout);
121+
isTimerActive = false;
120122
});
121123

122124
// @ts-expect-error - TypeScript can't narrow generic hook types to match specific overloads, but we know this is type-safe
@@ -127,10 +129,15 @@ function setupWeightBasedFlushing<
127129
// The weight is a rough estimate, so we flush way before the payload gets too big.
128130
if (weight >= 800_000) {
129131
flushFn(client);
130-
} else {
131-
clearTimeout(flushTimeout);
132+
} else if (!isTimerActive) {
133+
// Only start timer if one isn't already running.
134+
// This prevents flushing being delayed by items that arrive close to the timeout limit
135+
// and thus resetting the flushing timeout and delaying items being flushed.
136+
isTimerActive = true;
132137
flushTimeout = setTimeout(() => {
133138
flushFn(client);
139+
// Note: isTimerActive is reset by the flushHook handler above, not here,
140+
// to avoid race conditions when new items arrive during the flush.
134141
}, DEFAULT_FLUSH_INTERVAL);
135142
}
136143
});

packages/core/test/lib/client.test.ts

Lines changed: 34 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -2772,7 +2772,7 @@ describe('Client', () => {
27722772
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
27732773
});
27742774

2775-
it('resets idle timeout when new logs are captured', () => {
2775+
it('does not reset idle timeout when new logs are captured', () => {
27762776
const options = getDefaultTestClientOptions({
27772777
dsn: PUBLIC_DSN,
27782778
enableLogs: true,
@@ -2783,26 +2783,52 @@ describe('Client', () => {
27832783

27842784
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
27852785

2786-
// Add initial log
2786+
// Add initial log (starts the timer)
27872787
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, scope);
27882788

27892789
// Fast forward part of the idle timeout
27902790
vi.advanceTimersByTime(2500);
27912791

2792-
// Add another log which should reset the timeout
2792+
// Add another log which should NOT reset the timeout
27932793
_INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, scope);
27942794

2795-
// Fast forward the remaining time
2795+
// Fast forward the remaining time to reach the full timeout from the first log
27962796
vi.advanceTimersByTime(2500);
27972797

2798-
// Should not have flushed yet since timeout was reset
2799-
expect(sendEnvelopeSpy).not.toHaveBeenCalled();
2798+
// Should have flushed both logs since timeout was not reset
2799+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
2800+
});
2801+
2802+
it('starts new timer after timeout completes and flushes', () => {
2803+
const options = getDefaultTestClientOptions({
2804+
dsn: PUBLIC_DSN,
2805+
enableLogs: true,
2806+
});
2807+
const client = new TestClient(options);
2808+
const scope = new Scope();
2809+
scope.setClient(client);
28002810

2801-
// Fast forward the full timeout
2811+
const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope');
2812+
2813+
// First batch: Add a log and let it flush
2814+
_INTERNAL_captureLog({ message: 'test log 1', level: 'info' }, scope);
2815+
2816+
// Fast forward to trigger the first flush
28022817
vi.advanceTimersByTime(5000);
28032818

2804-
// Now should have flushed both logs
28052819
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
2820+
2821+
// Second batch: Add another log after the first flush completed
2822+
_INTERNAL_captureLog({ message: 'test log 2', level: 'info' }, scope);
2823+
2824+
// Should not have flushed yet
2825+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1);
2826+
2827+
// Fast forward to trigger the second flush
2828+
vi.advanceTimersByTime(5000);
2829+
2830+
// Should have flushed the second log
2831+
expect(sendEnvelopeSpy).toHaveBeenCalledTimes(2);
28062832
});
28072833

28082834
it('flushes logs on flush event', () => {

0 commit comments

Comments
 (0)