From d380e390ea51a294236c1d0de29a0b08a1bd4dbd Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 13:57:45 +0100 Subject: [PATCH 01/11] ref(replay): Pause recording when replay requests are rate-limited --- packages/replay/src/replay.ts | 51 +++++- .../test/integration/rateLimiting.test.ts | 154 ++++++++++++++++++ 2 files changed, 201 insertions(+), 4 deletions(-) create mode 100644 packages/replay/test/integration/rateLimiting.test.ts diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index e82908defa58..3428073dc4da 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1,7 +1,14 @@ /* eslint-disable max-lines */ // TODO: We might want to split this file up import { addGlobalEventProcessor, captureException, getCurrentHub, setContext } from '@sentry/core'; import type { Breadcrumb, ReplayEvent, ReplayRecordingMode, TransportMakeRequestResponse } from '@sentry/types'; -import { addInstrumentationHandler, logger } from '@sentry/utils'; +import { + addInstrumentationHandler, + disabledUntil, + isRateLimited, + logger, + RateLimits, + updateRateLimits, +} from '@sentry/utils'; import { EventType, record } from 'rrweb'; import { @@ -128,6 +135,11 @@ export class ReplayContainer implements ReplayContainerInterface { initialUrl: '', }; + /** + * A RateLimits object holding the rate-limit durations in case a sent replay event was rate-limited. + */ + private _rateLimits: RateLimits = {}; + public constructor({ options, recordingOptions, @@ -988,7 +1000,15 @@ export class ReplayContainer implements ReplayContainerInterface { const envelope = createReplayEnvelope(replayEvent, recordingData, dsn, client.getOptions().tunnel); try { - return await transport.send(envelope); + const response = await transport.send(envelope); + // TODO (v8): we can remove this guard once transport.end's type signature doesn't include void anymore + if (response) { + this._rateLimits = updateRateLimits(this._rateLimits, response); + if (isRateLimited(this._rateLimits, 'replay_event') || isRateLimited(this._rateLimits, 'replay_recording')) { + this._handleRateLimit(); + } + } + return response; } catch { throw new Error(UNABLE_TO_SEND_REPLAY); } @@ -1040,9 +1060,8 @@ export class ReplayContainer implements ReplayContainerInterface { throw new Error(`${UNABLE_TO_SEND_REPLAY} - max retries exceeded`); } - this._retryCount = this._retryCount + 1; // will retry in intervals of 5, 10, 30 - this._retryInterval = this._retryCount * this._retryInterval; + this._retryInterval = ++this._retryCount * this._retryInterval; return await new Promise((resolve, reject) => { setTimeout(async () => { @@ -1069,4 +1088,28 @@ export class ReplayContainer implements ReplayContainerInterface { saveSession(this.session); } } + + /** + * Pauses the replay and resumes it after the rate-limit duration is over. + */ + private _handleRateLimit(): void { + const rateLimitEnd = Math.max( + disabledUntil(this._rateLimits, 'replay_event'), + disabledUntil(this._rateLimits, 'replay_recording'), + ); + + const rateLimitDuration = rateLimitEnd - Date.now(); + + if (rateLimitDuration > 0) { + __DEBUG_BUILD__ && logger.warn('[Replay]', `Rate limit hit, pausing replay for ${rateLimitDuration}ms`); + this.pause(); + this._debouncedFlush && this._debouncedFlush.cancel(); + + setTimeout(() => { + __DEBUG_BUILD__ && logger.info('[Replay]', 'Resuming replay after rate limit'); + this.resume(); + this._debouncedFlush(); + }, rateLimitDuration); + } + } } diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts new file mode 100644 index 000000000000..bb31899907d6 --- /dev/null +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -0,0 +1,154 @@ +import { Transport, TransportMakeRequestResponse } from '@sentry/types'; +import { ReplayContainer } from '../../src/replay'; +import { BASE_TIMESTAMP, mockSdk } from '../index'; +import { mockRrweb } from '../mocks/mockRrweb'; +import { useFakeTimers } from '../utils/use-fake-timers'; +import { getCurrentHub } from '@sentry/core'; +import { clearSession } from '../utils/clearSession'; +import { DEFAULT_FLUSH_MIN_DELAY, SESSION_IDLE_DURATION } from '../../src/constants'; + +useFakeTimers(); + +async function advanceTimers(time: number) { + jest.advanceTimersByTime(time); + await new Promise(process.nextTick); +} + +type MockTransportSend = jest.MockedFunction; +type MockSendReplayRequest = jest.MockedFunction; + +describe('Integration | rate-limiting behaviour', () => { + let replay: ReplayContainer; + let mockTransportSend: MockTransportSend; + let mockSendReplayRequest: MockSendReplayRequest; + const { record: mockRecord } = mockRrweb(); + + beforeAll(async () => { + jest.setSystemTime(new Date(BASE_TIMESTAMP)); + + ({ replay } = await mockSdk({ + replayOptions: { + stickySession: false, + }, + })); + + jest.spyOn(replay, 'sendReplayRequest'); + + jest.runAllTimers(); + mockTransportSend = getCurrentHub()?.getClient()?.getTransport()?.send as MockTransportSend; + mockSendReplayRequest = replay.sendReplayRequest as MockSendReplayRequest; + }); + + beforeEach(() => { + jest.setSystemTime(new Date(BASE_TIMESTAMP)); + mockRecord.takeFullSnapshot.mockClear(); + mockTransportSend.mockClear(); + + // Create a new session and clear mocks because a segment (from initial + // checkout) will have already been uploaded by the time the tests run + clearSession(replay); + replay.loadSession({ expiry: 0 }); + + mockSendReplayRequest.mockClear(); + }); + + afterEach(async () => { + jest.runAllTimers(); + await new Promise(process.nextTick); + jest.setSystemTime(new Date(BASE_TIMESTAMP)); + clearSession(replay); + replay.loadSession({ expiry: SESSION_IDLE_DURATION }); + }); + + afterAll(() => { + replay && replay.stop(); + }); + + it('pauses recording and flushing a rate limit is hit and resumes both after the rate limit duration is over', async () => { + expect(replay.session?.segmentId).toBe(0); + jest.spyOn(replay, 'sendReplay'); + jest.spyOn(replay, 'pause'); + jest.spyOn(replay, 'resume'); + // @ts-ignore private API + jest.spyOn(replay, '_handleRateLimit'); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; + + mockTransportSend.mockImplementationOnce(() => { + return Promise.resolve({ + statusCode: 429, + headers: { + 'x-sentry-rate-limits': null, + 'retry-after': `30`, + }, + } as TransportMakeRequestResponse); + }); + + mockRecord._emitter(TEST_EVENT); + + // T = base + 5 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT]) }); + + expect(replay['_handleRateLimit']).toHaveBeenCalledTimes(1); + // resume() was called once before we even started + expect(replay.resume).not.toHaveBeenCalled(); + expect(replay.pause).toHaveBeenCalledTimes(1); + + // No user activity to trigger an update + expect(replay.session?.lastActivity).toBe(BASE_TIMESTAMP); + expect(replay.session?.segmentId).toBe(1); + + // let's simulate the rate-limit time of inactivity (30secs) and check that we don't do anything in the meantime + const TEST_EVENT2 = { data: {}, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, type: 3 }; + for (let i = 0; i < 5; i++) { + const ev = { + ...TEST_EVENT2, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * (i + 1), + }; + mockRecord._emitter(ev); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.isPaused()).toBe(true); + expect(replay.sendReplay).toHaveBeenCalledTimes(1); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + } + + // T = base + 35 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + // now, recording should resume and first, we expect a checkout event to be sent, as resume() + // should trigger a full snapshot + expect(replay.resume).toHaveBeenCalledTimes(1); + expect(replay.isPaused()).toBe(false); + + expect(replay.sendReplay).toHaveBeenCalledTimes(2); + expect(replay).toHaveLastSentReplay({ + events: '[{"data":{"isCheckout":true},"timestamp":1580598035000,"type":2}]', + }); + + // and let's also emit a new event and check that it is recorded + const TEST_EVENT3 = { + data: {}, + timestamp: BASE_TIMESTAMP + 7 * DEFAULT_FLUSH_MIN_DELAY, + type: 3, + }; + mockRecord._emitter(TEST_EVENT3); + + // T = base + 40 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // nothing should happen afterwards + // T = base + 60 + await advanceTimers(20_000); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // events array should be empty + expect(replay.eventBuffer?.length).toBe(0); + }); +}); From 5953fb03d6093880737ee210579329841c88d516 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 14:46:15 +0100 Subject: [PATCH 02/11] add tests for multiple rate limit headers --- .../test/integration/rateLimiting.test.ts | 197 ++++++++++-------- 1 file changed, 112 insertions(+), 85 deletions(-) diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index bb31899907d6..0409ccde718e 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -57,6 +57,7 @@ describe('Integration | rate-limiting behaviour', () => { await new Promise(process.nextTick); jest.setSystemTime(new Date(BASE_TIMESTAMP)); clearSession(replay); + jest.clearAllMocks(); replay.loadSession({ expiry: SESSION_IDLE_DURATION }); }); @@ -64,91 +65,117 @@ describe('Integration | rate-limiting behaviour', () => { replay && replay.stop(); }); - it('pauses recording and flushing a rate limit is hit and resumes both after the rate limit duration is over', async () => { - expect(replay.session?.segmentId).toBe(0); - jest.spyOn(replay, 'sendReplay'); - jest.spyOn(replay, 'pause'); - jest.spyOn(replay, 'resume'); - // @ts-ignore private API - jest.spyOn(replay, '_handleRateLimit'); - - const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; - - mockTransportSend.mockImplementationOnce(() => { - return Promise.resolve({ - statusCode: 429, - headers: { - 'x-sentry-rate-limits': null, - 'retry-after': `30`, - }, - } as TransportMakeRequestResponse); - }); - - mockRecord._emitter(TEST_EVENT); - - // T = base + 5 - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - - expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); - expect(mockTransportSend).toHaveBeenCalledTimes(1); - expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT]) }); - - expect(replay['_handleRateLimit']).toHaveBeenCalledTimes(1); - // resume() was called once before we even started - expect(replay.resume).not.toHaveBeenCalled(); - expect(replay.pause).toHaveBeenCalledTimes(1); - - // No user activity to trigger an update - expect(replay.session?.lastActivity).toBe(BASE_TIMESTAMP); - expect(replay.session?.segmentId).toBe(1); - - // let's simulate the rate-limit time of inactivity (30secs) and check that we don't do anything in the meantime - const TEST_EVENT2 = { data: {}, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, type: 3 }; - for (let i = 0; i < 5; i++) { - const ev = { - ...TEST_EVENT2, - timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * (i + 1), - }; - mockRecord._emitter(ev); + it.each([ + { + statusCode: 429, + headers: { + 'x-sentry-rate-limits': '30', + 'retry-after': null, + }, + }, + { + statusCode: 429, + headers: { + 'x-sentry-rate-limits': '30:replay_event', + 'retry-after': null, + }, + }, + { + statusCode: 429, + headers: { + 'x-sentry-rate-limits': '30:replay_recording', + 'retry-after': null, + }, + }, + { + statusCode: 429, + headers: { + 'x-sentry-rate-limits': null, + 'retry-after': '30', + }, + }, + ] as TransportMakeRequestResponse[])( + 'pauses recording and flushing a rate limit is hit and resumes both after the rate limit duration is over', + async rateLimitResponse => { + expect(replay.session?.segmentId).toBe(0); + jest.spyOn(replay, 'sendReplay'); + jest.spyOn(replay, 'pause'); + jest.spyOn(replay, 'resume'); + // @ts-ignore private API + jest.spyOn(replay, '_handleRateLimit'); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; + + mockTransportSend.mockImplementationOnce(() => { + return Promise.resolve(rateLimitResponse); + }); + + mockRecord._emitter(TEST_EVENT); + + // T = base + 5 await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - expect(replay.isPaused()).toBe(true); - expect(replay.sendReplay).toHaveBeenCalledTimes(1); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); expect(mockTransportSend).toHaveBeenCalledTimes(1); - } - - // T = base + 35 - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - - // now, recording should resume and first, we expect a checkout event to be sent, as resume() - // should trigger a full snapshot - expect(replay.resume).toHaveBeenCalledTimes(1); - expect(replay.isPaused()).toBe(false); - - expect(replay.sendReplay).toHaveBeenCalledTimes(2); - expect(replay).toHaveLastSentReplay({ - events: '[{"data":{"isCheckout":true},"timestamp":1580598035000,"type":2}]', - }); - - // and let's also emit a new event and check that it is recorded - const TEST_EVENT3 = { - data: {}, - timestamp: BASE_TIMESTAMP + 7 * DEFAULT_FLUSH_MIN_DELAY, - type: 3, - }; - mockRecord._emitter(TEST_EVENT3); - - // T = base + 40 - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); - expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); - - // nothing should happen afterwards - // T = base + 60 - await advanceTimers(20_000); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); - expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); - - // events array should be empty - expect(replay.eventBuffer?.length).toBe(0); - }); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT]) }); + + expect(replay['_handleRateLimit']).toHaveBeenCalledTimes(1); + // resume() was called once before we even started + expect(replay.resume).not.toHaveBeenCalled(); + expect(replay.pause).toHaveBeenCalledTimes(1); + + // No user activity to trigger an update + expect(replay.session?.lastActivity).toBe(BASE_TIMESTAMP); + expect(replay.session?.segmentId).toBe(1); + + // let's simulate the rate-limit time of inactivity (30secs) and check that we don't do anything in the meantime + const TEST_EVENT2 = { data: {}, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, type: 3 }; + for (let i = 0; i < 5; i++) { + const ev = { + ...TEST_EVENT2, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * (i + 1), + }; + mockRecord._emitter(ev); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.isPaused()).toBe(true); + expect(replay.sendReplay).toHaveBeenCalledTimes(1); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + } + + // T = base + 35 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + // now, recording should resume and first, we expect a checkout event to be sent, as resume() + // should trigger a full snapshot + expect(replay.resume).toHaveBeenCalledTimes(1); + expect(replay.isPaused()).toBe(false); + + expect(replay.sendReplay).toHaveBeenCalledTimes(2); + expect(replay).toHaveLastSentReplay({ + events: '[{"data":{"isCheckout":true},"timestamp":1580598035000,"type":2}]', + }); + + // and let's also emit a new event and check that it is recorded + const TEST_EVENT3 = { + data: {}, + timestamp: BASE_TIMESTAMP + 7 * DEFAULT_FLUSH_MIN_DELAY, + type: 3, + }; + mockRecord._emitter(TEST_EVENT3); + + // T = base + 40 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // nothing should happen afterwards + // T = base + 60 + await advanceTimers(20_000); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // events array should be empty + expect(replay.eventBuffer?.length).toBe(0); + }, + ); }); From 3808b24538e7c9147128944c17189ff039745175 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 17:41:04 +0100 Subject: [PATCH 03/11] remove unnecessary debouncedFlush call --- packages/replay/src/replay.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index 3428073dc4da..b93e786670c0 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1108,7 +1108,6 @@ export class ReplayContainer implements ReplayContainerInterface { setTimeout(() => { __DEBUG_BUILD__ && logger.info('[Replay]', 'Resuming replay after rate limit'); this.resume(); - this._debouncedFlush(); }, rateLimitDuration); } } From 12429c8989520d1a8472647565f8fded10b50958 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 17:45:23 +0100 Subject: [PATCH 04/11] use correct rate limit category --- packages/replay/src/replay.ts | 8 ++------ packages/replay/test/integration/rateLimiting.test.ts | 9 +-------- 2 files changed, 3 insertions(+), 14 deletions(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index b93e786670c0..e48ed2224676 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1004,7 +1004,7 @@ export class ReplayContainer implements ReplayContainerInterface { // TODO (v8): we can remove this guard once transport.end's type signature doesn't include void anymore if (response) { this._rateLimits = updateRateLimits(this._rateLimits, response); - if (isRateLimited(this._rateLimits, 'replay_event') || isRateLimited(this._rateLimits, 'replay_recording')) { + if (isRateLimited(this._rateLimits, 'replay')) { this._handleRateLimit(); } } @@ -1093,11 +1093,7 @@ export class ReplayContainer implements ReplayContainerInterface { * Pauses the replay and resumes it after the rate-limit duration is over. */ private _handleRateLimit(): void { - const rateLimitEnd = Math.max( - disabledUntil(this._rateLimits, 'replay_event'), - disabledUntil(this._rateLimits, 'replay_recording'), - ); - + const rateLimitEnd = disabledUntil(this._rateLimits, 'replay'); const rateLimitDuration = rateLimitEnd - Date.now(); if (rateLimitDuration > 0) { diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index 0409ccde718e..c8ad70314151 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -76,14 +76,7 @@ describe('Integration | rate-limiting behaviour', () => { { statusCode: 429, headers: { - 'x-sentry-rate-limits': '30:replay_event', - 'retry-after': null, - }, - }, - { - statusCode: 429, - headers: { - 'x-sentry-rate-limits': '30:replay_recording', + 'x-sentry-rate-limits': '30:replay', 'retry-after': null, }, }, From d5fccde1f342559732258ae4f206e31275818c72 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 18:25:29 +0100 Subject: [PATCH 05/11] add test for a plain 429 response w/o retry-after period --- .../test/integration/rateLimiting.test.ts | 85 +++++++++++++++++++ 1 file changed, 85 insertions(+) diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index c8ad70314151..0371ed4f12cd 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -50,6 +50,8 @@ describe('Integration | rate-limiting behaviour', () => { replay.loadSession({ expiry: 0 }); mockSendReplayRequest.mockClear(); + + replay['_rateLimits'] = {}; }); afterEach(async () => { @@ -171,4 +173,87 @@ describe('Integration | rate-limiting behaviour', () => { expect(replay.eventBuffer?.length).toBe(0); }, ); + + it('handles rate-limits from a plain 429 response without any retry time', async () => { + expect(replay.session?.segmentId).toBe(0); + jest.spyOn(replay, 'sendReplay'); + jest.spyOn(replay, 'pause'); + jest.spyOn(replay, 'resume'); + // @ts-ignore private API + jest.spyOn(replay, '_handleRateLimit'); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; + + mockTransportSend.mockImplementationOnce(() => { + return Promise.resolve({ statusCode: 429 }); + }); + + mockRecord._emitter(TEST_EVENT); + + // T = base + 5 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT]) }); + + expect(replay['_handleRateLimit']).toHaveBeenCalledTimes(1); + // resume() was called once before we even started + expect(replay.resume).not.toHaveBeenCalled(); + expect(replay.pause).toHaveBeenCalledTimes(1); + + // No user activity to trigger an update + expect(replay.session?.lastActivity).toBe(BASE_TIMESTAMP); + expect(replay.session?.segmentId).toBe(1); + + // let's simulate the rate-limit time of inactivity (60secs) and check that we don't do anything in the meantime + // 60secs are the default we fall back to in the plain 429 case in updateRateLimits() + const TEST_EVENT2 = { data: {}, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, type: 3 }; + for (let i = 0; i < 11; i++) { + const ev = { + ...TEST_EVENT2, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * (i + 1), + }; + mockRecord._emitter(ev); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.isPaused()).toBe(true); + expect(replay.sendReplay).toHaveBeenCalledTimes(1); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + } + + // T = base + 60 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + // now, recording should resume and first, we expect a checkout event to be sent, as resume() + // should trigger a full snapshot + expect(replay.resume).toHaveBeenCalledTimes(1); + expect(replay.isPaused()).toBe(false); + + expect(replay.sendReplay).toHaveBeenCalledTimes(2); + expect(replay).toHaveLastSentReplay({ + events: '[{"data":{"isCheckout":true},"timestamp":1580598065000,"type":2}]', + }); + + // and let's also emit a new event and check that it is recorded + const TEST_EVENT3 = { + data: {}, + timestamp: BASE_TIMESTAMP + 7 * DEFAULT_FLUSH_MIN_DELAY, + type: 3, + }; + mockRecord._emitter(TEST_EVENT3); + + // T = base + 65 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // nothing should happen afterwards + // T = base + 85 + await advanceTimers(20_000); + expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); + + // events array should be empty + expect(replay.eventBuffer?.length).toBe(0); + }); }); From 8d89c064fb978b887a877c37b0b8db2e5c4af948 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Wed, 11 Jan 2023 18:28:23 +0100 Subject: [PATCH 06/11] fix typo --- packages/replay/src/replay.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index e48ed2224676..9ddc36aeb2ea 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1001,7 +1001,7 @@ export class ReplayContainer implements ReplayContainerInterface { try { const response = await transport.send(envelope); - // TODO (v8): we can remove this guard once transport.end's type signature doesn't include void anymore + // TODO (v8): we can remove this guard once transport.send's type signature doesn't include void anymore if (response) { this._rateLimits = updateRateLimits(this._rateLimits, response); if (isRateLimited(this._rateLimits, 'replay')) { From 2d94cab9c5ac270c20269df727852013b72bd59f Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Thu, 12 Jan 2023 12:29:05 +0100 Subject: [PATCH 07/11] update tests after rebase --- .../test/integration/rateLimiting.test.ts | 37 ++++++++++--------- 1 file changed, 20 insertions(+), 17 deletions(-) diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index 0371ed4f12cd..3803d5a1ae31 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -15,7 +15,7 @@ async function advanceTimers(time: number) { } type MockTransportSend = jest.MockedFunction; -type MockSendReplayRequest = jest.MockedFunction; +type MockSendReplayRequest = jest.MockedFunction; describe('Integration | rate-limiting behaviour', () => { let replay: ReplayContainer; @@ -32,11 +32,12 @@ describe('Integration | rate-limiting behaviour', () => { }, })); - jest.spyOn(replay, 'sendReplayRequest'); + // @ts-ignore private API + jest.spyOn(replay, '_sendReplayRequest'); jest.runAllTimers(); mockTransportSend = getCurrentHub()?.getClient()?.getTransport()?.send as MockTransportSend; - mockSendReplayRequest = replay.sendReplayRequest as MockSendReplayRequest; + mockSendReplayRequest = replay['_sendReplayRequest'] as MockSendReplayRequest; }); beforeEach(() => { @@ -47,7 +48,7 @@ describe('Integration | rate-limiting behaviour', () => { // Create a new session and clear mocks because a segment (from initial // checkout) will have already been uploaded by the time the tests run clearSession(replay); - replay.loadSession({ expiry: 0 }); + replay['_loadSession']({ expiry: 0 }); mockSendReplayRequest.mockClear(); @@ -60,7 +61,7 @@ describe('Integration | rate-limiting behaviour', () => { jest.setSystemTime(new Date(BASE_TIMESTAMP)); clearSession(replay); jest.clearAllMocks(); - replay.loadSession({ expiry: SESSION_IDLE_DURATION }); + replay['_loadSession']({ expiry: SESSION_IDLE_DURATION }); }); afterAll(() => { @@ -93,11 +94,12 @@ describe('Integration | rate-limiting behaviour', () => { 'pauses recording and flushing a rate limit is hit and resumes both after the rate limit duration is over', async rateLimitResponse => { expect(replay.session?.segmentId).toBe(0); - jest.spyOn(replay, 'sendReplay'); jest.spyOn(replay, 'pause'); jest.spyOn(replay, 'resume'); // @ts-ignore private API jest.spyOn(replay, '_handleRateLimit'); + // @ts-ignore private API + jest.spyOn(replay, '_sendReplay'); const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; @@ -133,7 +135,7 @@ describe('Integration | rate-limiting behaviour', () => { mockRecord._emitter(ev); await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); expect(replay.isPaused()).toBe(true); - expect(replay.sendReplay).toHaveBeenCalledTimes(1); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(1); expect(mockTransportSend).toHaveBeenCalledTimes(1); } @@ -145,7 +147,7 @@ describe('Integration | rate-limiting behaviour', () => { expect(replay.resume).toHaveBeenCalledTimes(1); expect(replay.isPaused()).toBe(false); - expect(replay.sendReplay).toHaveBeenCalledTimes(2); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(2); expect(replay).toHaveLastSentReplay({ events: '[{"data":{"isCheckout":true},"timestamp":1580598035000,"type":2}]', }); @@ -160,27 +162,28 @@ describe('Integration | rate-limiting behaviour', () => { // T = base + 40 await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(3); expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); // nothing should happen afterwards // T = base + 60 await advanceTimers(20_000); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(3); expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); // events array should be empty - expect(replay.eventBuffer?.length).toBe(0); + expect(replay.eventBuffer?.pendingLength).toBe(0); }, ); it('handles rate-limits from a plain 429 response without any retry time', async () => { expect(replay.session?.segmentId).toBe(0); - jest.spyOn(replay, 'sendReplay'); jest.spyOn(replay, 'pause'); jest.spyOn(replay, 'resume'); // @ts-ignore private API jest.spyOn(replay, '_handleRateLimit'); + // @ts-ignore private API + jest.spyOn(replay, '_sendReplay'); const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; @@ -217,7 +220,7 @@ describe('Integration | rate-limiting behaviour', () => { mockRecord._emitter(ev); await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); expect(replay.isPaused()).toBe(true); - expect(replay.sendReplay).toHaveBeenCalledTimes(1); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(1); expect(mockTransportSend).toHaveBeenCalledTimes(1); } @@ -229,7 +232,7 @@ describe('Integration | rate-limiting behaviour', () => { expect(replay.resume).toHaveBeenCalledTimes(1); expect(replay.isPaused()).toBe(false); - expect(replay.sendReplay).toHaveBeenCalledTimes(2); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(2); expect(replay).toHaveLastSentReplay({ events: '[{"data":{"isCheckout":true},"timestamp":1580598065000,"type":2}]', }); @@ -244,16 +247,16 @@ describe('Integration | rate-limiting behaviour', () => { // T = base + 65 await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(3); expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); // nothing should happen afterwards // T = base + 85 await advanceTimers(20_000); - expect(replay.sendReplay).toHaveBeenCalledTimes(3); + expect(replay['_sendReplay']).toHaveBeenCalledTimes(3); expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT3]) }); // events array should be empty - expect(replay.eventBuffer?.length).toBe(0); + expect(replay.eventBuffer?.pendingLength).toBe(0); }); }); From 88fec71f04779b32e771e21ef540523a12f65a2b Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Thu, 12 Jan 2023 13:19:01 +0100 Subject: [PATCH 08/11] don't do anything if already paused --- packages/replay/src/replay.ts | 10 ++++++ .../test/integration/rateLimiting.test.ts | 34 +++++++++++++++++++ 2 files changed, 44 insertions(+) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index 9ddc36aeb2ea..528f7b538aaa 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -275,6 +275,10 @@ export class ReplayContainer implements ReplayContainerInterface { * not as thorough of a shutdown as `stop()`. */ public pause(): void { + console.log('I was called'); + + console.trace(); + this._isPaused = true; try { if (this._stopRecording) { @@ -1093,6 +1097,12 @@ export class ReplayContainer implements ReplayContainerInterface { * Pauses the replay and resumes it after the rate-limit duration is over. */ private _handleRateLimit(): void { + // in case recording is already paused, we don't need to do anything, as we might have already paused because of a + // rate limit + if (this.isPaused()) { + return; + } + const rateLimitEnd = disabledUntil(this._rateLimits, 'replay'); const rateLimitDuration = rateLimitEnd - Date.now(); diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index 3803d5a1ae31..6eb6cbb37cf3 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -259,4 +259,38 @@ describe('Integration | rate-limiting behaviour', () => { // events array should be empty expect(replay.eventBuffer?.pendingLength).toBe(0); }); + + it("doesn't do anything, if a rate limit is hit and recording is already paused", async () => { + let paused = false; + expect(replay.session?.segmentId).toBe(0); + jest.spyOn(replay, 'isPaused').mockImplementation(() => { + return paused; + }); + jest.spyOn(replay, 'pause'); + jest.spyOn(replay, 'resume'); + // @ts-ignore private API + jest.spyOn(replay, '_handleRateLimit'); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; + + mockTransportSend.mockImplementationOnce(() => { + return Promise.resolve({ statusCode: 429 }); + }); + + mockRecord._emitter(TEST_EVENT); + paused = true; + + // T = base + 5 + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(mockTransportSend).toHaveBeenCalledTimes(1); + + expect(replay).toHaveLastSentReplay({ events: JSON.stringify([TEST_EVENT]) }); + + expect(replay['_handleRateLimit']).toHaveBeenCalledTimes(1); + expect(replay.resume).not.toHaveBeenCalled(); + expect(replay.isPaused).toHaveBeenCalledTimes(2); + expect(replay.pause).not.toHaveBeenCalled(); + }); }); From dbe4e9da1715f88f1cc9041ccd9d1608071435ab Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Thu, 12 Jan 2023 14:39:42 +0100 Subject: [PATCH 09/11] fix linter errors --- packages/replay/src/replay.ts | 14 ++------------ .../replay/test/integration/rateLimiting.test.ts | 11 ++++++----- 2 files changed, 8 insertions(+), 17 deletions(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index 528f7b538aaa..06a8ae58f64a 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1,14 +1,8 @@ /* eslint-disable max-lines */ // TODO: We might want to split this file up import { addGlobalEventProcessor, captureException, getCurrentHub, setContext } from '@sentry/core'; import type { Breadcrumb, ReplayEvent, ReplayRecordingMode, TransportMakeRequestResponse } from '@sentry/types'; -import { - addInstrumentationHandler, - disabledUntil, - isRateLimited, - logger, - RateLimits, - updateRateLimits, -} from '@sentry/utils'; +import type { RateLimits } from '@sentry/utils'; +import { addInstrumentationHandler, disabledUntil, isRateLimited, logger, updateRateLimits } from '@sentry/utils'; import { EventType, record } from 'rrweb'; import { @@ -275,10 +269,6 @@ export class ReplayContainer implements ReplayContainerInterface { * not as thorough of a shutdown as `stop()`. */ public pause(): void { - console.log('I was called'); - - console.trace(); - this._isPaused = true; try { if (this._stopRecording) { diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index 6eb6cbb37cf3..f9b9f6af3c95 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -1,11 +1,12 @@ -import { Transport, TransportMakeRequestResponse } from '@sentry/types'; -import { ReplayContainer } from '../../src/replay'; +import { getCurrentHub } from '@sentry/core'; +import type { Transport, TransportMakeRequestResponse } from '@sentry/types'; + +import { DEFAULT_FLUSH_MIN_DELAY, SESSION_IDLE_DURATION } from '../../src/constants'; +import type { ReplayContainer } from '../../src/replay'; import { BASE_TIMESTAMP, mockSdk } from '../index'; import { mockRrweb } from '../mocks/mockRrweb'; -import { useFakeTimers } from '../utils/use-fake-timers'; -import { getCurrentHub } from '@sentry/core'; import { clearSession } from '../utils/clearSession'; -import { DEFAULT_FLUSH_MIN_DELAY, SESSION_IDLE_DURATION } from '../../src/constants'; +import { useFakeTimers } from '../utils/use-fake-timers'; useFakeTimers(); From 6d61f5b5fa8d0f22ba2d20871a300a1a13d14520 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Thu, 12 Jan 2023 15:13:56 +0100 Subject: [PATCH 10/11] fix test on CI --- packages/replay/test/integration/rateLimiting.test.ts | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/packages/replay/test/integration/rateLimiting.test.ts b/packages/replay/test/integration/rateLimiting.test.ts index f9b9f6af3c95..1270d7c9d780 100644 --- a/packages/replay/test/integration/rateLimiting.test.ts +++ b/packages/replay/test/integration/rateLimiting.test.ts @@ -150,7 +150,9 @@ describe('Integration | rate-limiting behaviour', () => { expect(replay['_sendReplay']).toHaveBeenCalledTimes(2); expect(replay).toHaveLastSentReplay({ - events: '[{"data":{"isCheckout":true},"timestamp":1580598035000,"type":2}]', + events: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * 7, type: 2 }, + ]), }); // and let's also emit a new event and check that it is recorded @@ -235,7 +237,9 @@ describe('Integration | rate-limiting behaviour', () => { expect(replay['_sendReplay']).toHaveBeenCalledTimes(2); expect(replay).toHaveLastSentReplay({ - events: '[{"data":{"isCheckout":true},"timestamp":1580598065000,"type":2}]', + events: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY * 13, type: 2 }, + ]), }); // and let's also emit a new event and check that it is recorded From 3b0f7ba551af439f52f34c870a58e36cbffe92e4 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Thu, 12 Jan 2023 15:45:46 +0100 Subject: [PATCH 11/11] increase integration test timeout --- packages/integration-tests/suites/replay/captureReplay/test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/integration-tests/suites/replay/captureReplay/test.ts b/packages/integration-tests/suites/replay/captureReplay/test.ts index 80a3f52201dd..51a1d900f9ed 100644 --- a/packages/integration-tests/suites/replay/captureReplay/test.ts +++ b/packages/integration-tests/suites/replay/captureReplay/test.ts @@ -23,7 +23,7 @@ sentryTest('captureReplay', async ({ getLocalTestPath, page }) => { await page.goto(url); await page.click('button'); - await page.waitForTimeout(200); + await page.waitForTimeout(300); const replayEvent = await getFirstSentryEnvelopeRequest(page, url);