From 29e8911d17eb80c738fcb2d3c455a2ddc2c61ea4 Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Mon, 24 Apr 2023 23:05:33 +0200 Subject: [PATCH 1/6] feat(replay): Do not capture replays < 5 seconds Do not immediately flush on snapshot checkouts, instead delay by minimum flush delay (5 seconds). This means that we will not collect replays < 5 seconds. e.g. User opens site and immediately closes the tab. Closes https://github.com/getsentry/team-replay/issues/63 --- packages/replay/src/replay.ts | 32 ++++++++++------- packages/replay/src/types.ts | 2 ++ .../replay/src/util/handleRecordingEmit.ts | 24 ++++++++++--- .../coreHandlers/handleAfterSendEvent.test.ts | 13 +++++-- .../test/integration/errorSampleRate.test.ts | 34 ++++++++----------- 5 files changed, 65 insertions(+), 40 deletions(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index 8d89aa0b2653..e45830e9fdde 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -463,7 +463,17 @@ export class ReplayContainer implements ReplayContainerInterface { } /** - * + * Only flush if `this.recordingMode === 'session'` + */ + public conditionalFlush(): Promise { + if (this.recordingMode === 'buffer') { + return Promise.resolve(); + } + + return this.flushImmediate(); + } + + /** * Always flush via `_debouncedFlush` so that we do not have flushes triggered * from calling both `flush` and `_debouncedFlush`. Otherwise, there could be * cases of mulitple flushes happening closely together. @@ -474,6 +484,13 @@ export class ReplayContainer implements ReplayContainerInterface { return this._debouncedFlush.flush() as Promise; } + /** + * Cancels queued up flushes. + */ + public cancelFlush(): void { + this._debouncedFlush.cancel(); + } + /** Get the current sesion (=replay) ID */ public getSessionId(): string | undefined { return this.session && this.session.id; @@ -723,7 +740,7 @@ export class ReplayContainer implements ReplayContainerInterface { // Send replay when the page/tab becomes hidden. There is no reason to send // replay if it becomes visible, since no actions we care about were done // while it was hidden - this._conditionalFlush(); + void this.conditionalFlush(); } /** @@ -807,17 +824,6 @@ export class ReplayContainer implements ReplayContainerInterface { return Promise.all(createPerformanceSpans(this, createPerformanceEntries(entries))); } - /** - * Only flush if `this.recordingMode === 'session'` - */ - private _conditionalFlush(): void { - if (this.recordingMode === 'buffer') { - return; - } - - void this.flushImmediate(); - } - /** * Clear _context */ diff --git a/packages/replay/src/types.ts b/packages/replay/src/types.ts index 12900dc22e74..a0a87a2a2320 100644 --- a/packages/replay/src/types.ts +++ b/packages/replay/src/types.ts @@ -515,7 +515,9 @@ export interface ReplayContainer { startRecording(): void; stopRecording(): boolean; sendBufferedReplayOrFlush(options?: SendBufferedReplayOptions): Promise; + conditionalFlush(): Promise; flushImmediate(): Promise; + cancelFlush(): void; triggerUserActivity(): void; addUpdate(cb: AddUpdateCallback): void; getOptions(): ReplayPluginOptions; diff --git a/packages/replay/src/util/handleRecordingEmit.ts b/packages/replay/src/util/handleRecordingEmit.ts index f72850f5536c..a841a9868298 100644 --- a/packages/replay/src/util/handleRecordingEmit.ts +++ b/packages/replay/src/util/handleRecordingEmit.ts @@ -84,10 +84,26 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa // it can prevent loading on the UI. This will cause an increase in short // replays (e.g. opening and closing a tab quickly), but these can be // filtered on the UI. - if (replay.recordingMode === 'session') { - // We want to ensure the worker is ready, as otherwise we'd always send the first event uncompressed - void replay.flushImmediate(); - } + // if (replay.recordingMode === 'session') { + // // We want to ensure the worker is ready, as otherwise we'd always send the first event uncompressed + // void replay.flushImmediate(); + // } + + // If the full snapshot is due to an initial load, we will not have + // a previous session ID. In this case, we want to buffer events + // for a set amount of time before flushing. This can help avoid + // capturing replays of users that immediately close the window. + setTimeout(() => replay.conditionalFlush(), replay.getOptions().flushMinDelay); + + // Cancel any previously debounced flushes to ensure there are no [near] + // simultaneous flushes happening. The latter request should be + // insignificant in this case, so wait for additional user interaction to + // trigger a new flush. + // + // This can happen because there's no guarantee that a recording event + // happens first. e.g. a mouse click can happen and trigger a debounced + // flush before the checkout. + replay.cancelFlush(); return true; }); diff --git a/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts b/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts index 1e59a4f7eef0..dc49f71e33ee 100644 --- a/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts +++ b/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts @@ -1,7 +1,7 @@ import { getCurrentHub } from '@sentry/core'; import type { ErrorEvent, Event } from '@sentry/types'; -import { UNABLE_TO_SEND_REPLAY } from '../../../src/constants'; +import { UNABLE_TO_SEND_REPLAY, DEFAULT_FLUSH_MIN_DELAY } from '../../../src/constants'; import { handleAfterSendEvent } from '../../../src/coreHandlers/handleAfterSendEvent'; import type { ReplayContainer } from '../../../src/replay'; import { Error } from '../../fixtures/error'; @@ -146,11 +146,18 @@ describe('Integration | coreHandlers | handleAfterSendEvent', () => { expect(Array.from(replay.getContext().errorIds)).toEqual(['err1']); - jest.runAllTimers(); + jest.runAllTimers() + await new Promise(process.nextTick); + + // Flush from the error + expect(mockSend).toHaveBeenCalledTimes(1); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); await new Promise(process.nextTick); - // Send twice, one for the error & one right after for the session conversion + // Flush for converting to session-based replay (startRecording call) expect(mockSend).toHaveBeenCalledTimes(2); + // This is removed now, because it has been converted to a "session" session expect(Array.from(replay.getContext().errorIds)).toEqual([]); expect(replay.isEnabled()).toBe(true); diff --git a/packages/replay/test/integration/errorSampleRate.test.ts b/packages/replay/test/integration/errorSampleRate.test.ts index 74fde11f50f0..8527690c2ebe 100644 --- a/packages/replay/test/integration/errorSampleRate.test.ts +++ b/packages/replay/test/integration/errorSampleRate.test.ts @@ -96,6 +96,9 @@ describe('Integration | errorSampleRate', () => { ]), }); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + // This is from when we stop recording and start a session recording expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 1 }, @@ -107,20 +110,6 @@ describe('Integration | errorSampleRate', () => { ]), }); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - - // New checkout when we call `startRecording` again after uploading segment - // after an error occurs - expect(replay).toHaveLastSentReplay({ - recordingData: JSON.stringify([ - { - data: { isCheckout: true }, - timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, - type: 2, - }, - ]), - }); - // Check that click will get captured domHandler({ name: 'click', @@ -130,14 +119,15 @@ describe('Integration | errorSampleRate', () => { await new Promise(process.nextTick); expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 2 }, recordingData: JSON.stringify([ { type: 5, - timestamp: BASE_TIMESTAMP + 10000 + 60, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80, data: { tag: 'breadcrumb', payload: { - timestamp: (BASE_TIMESTAMP + 10000 + 60) / 1000, + timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80) / 1000, type: 'default', category: 'ui.click', message: '', @@ -630,6 +620,10 @@ describe('Integration | errorSampleRate', () => { expect(replay).toHaveLastSentReplay(); + // Flush from calling `stopRecording` + jest.runAllTimers() + await new Promise(process.nextTick); + // Now wait after session expires - should stop recording mockRecord.takeFullSnapshot.mockClear(); (getCurrentHub().getClient()!.getTransport()!.send as unknown as jest.SpyInstance).mockClear(); @@ -736,10 +730,9 @@ it('sends a replay after loading the session multiple times', async () => { captureException(new Error('testing')); await new Promise(process.nextTick); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); - expect(replay).toHaveSentReplay({ + expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 0 }, recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, @@ -748,10 +741,11 @@ it('sends a replay after loading the session multiple times', async () => { ]), }); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); // Latest checkout when we call `startRecording` again after uploading segment // after an error occurs (e.g. when we switch to session replay recording) expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 1 }, - recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 5040, type: 2 }]), + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 10040, type: 2 }]), }); }); From 63234ec36bbfc7a6d499f11a447516e4e5560371 Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Tue, 25 Apr 2023 12:27:02 +0200 Subject: [PATCH 2/6] revert test changes --- .../coreHandlers/handleAfterSendEvent.test.ts | 13 ++----- .../test/integration/errorSampleRate.test.ts | 34 +++++++++++-------- 2 files changed, 23 insertions(+), 24 deletions(-) diff --git a/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts b/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts index dc49f71e33ee..1e59a4f7eef0 100644 --- a/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts +++ b/packages/replay/test/integration/coreHandlers/handleAfterSendEvent.test.ts @@ -1,7 +1,7 @@ import { getCurrentHub } from '@sentry/core'; import type { ErrorEvent, Event } from '@sentry/types'; -import { UNABLE_TO_SEND_REPLAY, DEFAULT_FLUSH_MIN_DELAY } from '../../../src/constants'; +import { UNABLE_TO_SEND_REPLAY } from '../../../src/constants'; import { handleAfterSendEvent } from '../../../src/coreHandlers/handleAfterSendEvent'; import type { ReplayContainer } from '../../../src/replay'; import { Error } from '../../fixtures/error'; @@ -146,18 +146,11 @@ describe('Integration | coreHandlers | handleAfterSendEvent', () => { expect(Array.from(replay.getContext().errorIds)).toEqual(['err1']); - jest.runAllTimers() - await new Promise(process.nextTick); - - // Flush from the error - expect(mockSend).toHaveBeenCalledTimes(1); - - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + jest.runAllTimers(); await new Promise(process.nextTick); - // Flush for converting to session-based replay (startRecording call) + // Send twice, one for the error & one right after for the session conversion expect(mockSend).toHaveBeenCalledTimes(2); - // This is removed now, because it has been converted to a "session" session expect(Array.from(replay.getContext().errorIds)).toEqual([]); expect(replay.isEnabled()).toBe(true); diff --git a/packages/replay/test/integration/errorSampleRate.test.ts b/packages/replay/test/integration/errorSampleRate.test.ts index 8527690c2ebe..74fde11f50f0 100644 --- a/packages/replay/test/integration/errorSampleRate.test.ts +++ b/packages/replay/test/integration/errorSampleRate.test.ts @@ -96,9 +96,6 @@ describe('Integration | errorSampleRate', () => { ]), }); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); - // This is from when we stop recording and start a session recording expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 1 }, @@ -110,6 +107,20 @@ describe('Integration | errorSampleRate', () => { ]), }); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + + // New checkout when we call `startRecording` again after uploading segment + // after an error occurs + expect(replay).toHaveLastSentReplay({ + recordingData: JSON.stringify([ + { + data: { isCheckout: true }, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, + type: 2, + }, + ]), + }); + // Check that click will get captured domHandler({ name: 'click', @@ -119,15 +130,14 @@ describe('Integration | errorSampleRate', () => { await new Promise(process.nextTick); expect(replay).toHaveLastSentReplay({ - recordingPayloadHeader: { segment_id: 2 }, recordingData: JSON.stringify([ { type: 5, - timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80, + timestamp: BASE_TIMESTAMP + 10000 + 60, data: { tag: 'breadcrumb', payload: { - timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80) / 1000, + timestamp: (BASE_TIMESTAMP + 10000 + 60) / 1000, type: 'default', category: 'ui.click', message: '', @@ -620,10 +630,6 @@ describe('Integration | errorSampleRate', () => { expect(replay).toHaveLastSentReplay(); - // Flush from calling `stopRecording` - jest.runAllTimers() - await new Promise(process.nextTick); - // Now wait after session expires - should stop recording mockRecord.takeFullSnapshot.mockClear(); (getCurrentHub().getClient()!.getTransport()!.send as unknown as jest.SpyInstance).mockClear(); @@ -730,9 +736,10 @@ it('sends a replay after loading the session multiple times', async () => { captureException(new Error('testing')); await new Promise(process.nextTick); - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); - expect(replay).toHaveLastSentReplay({ + expect(replay).toHaveSentReplay({ recordingPayloadHeader: { segment_id: 0 }, recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, @@ -741,11 +748,10 @@ it('sends a replay after loading the session multiple times', async () => { ]), }); - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); // Latest checkout when we call `startRecording` again after uploading segment // after an error occurs (e.g. when we switch to session replay recording) expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 1 }, - recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 10040, type: 2 }]), + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 5040, type: 2 }]), }); }); From a1a04752f52e6628dcfa1628782e758edc4c8cb4 Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Tue, 25 Apr 2023 12:27:18 +0200 Subject: [PATCH 3/6] change to use experiment --- packages/replay/src/types.ts | 1 + .../replay/src/util/handleRecordingEmit.ts | 48 +- .../errorSampleRate-delayFlush.test.ts | 650 ++++++++++++++++++ 3 files changed, 679 insertions(+), 20 deletions(-) create mode 100644 packages/replay/test/integration/errorSampleRate-delayFlush.test.ts diff --git a/packages/replay/src/types.ts b/packages/replay/src/types.ts index a0a87a2a2320..dfeeb0982194 100644 --- a/packages/replay/src/types.ts +++ b/packages/replay/src/types.ts @@ -285,6 +285,7 @@ export interface ReplayPluginOptions extends ReplayNetworkOptions { scrollTimeout: number; ignoreSelectors: string[]; }; + delayFlushOnCheckout: number; }>; } diff --git a/packages/replay/src/util/handleRecordingEmit.ts b/packages/replay/src/util/handleRecordingEmit.ts index a841a9868298..3a9dcc211edd 100644 --- a/packages/replay/src/util/handleRecordingEmit.ts +++ b/packages/replay/src/util/handleRecordingEmit.ts @@ -80,30 +80,38 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa } } + const options = replay.getOptions(); + + // TODO: We want this as an experiment so that we can test + // internally and create metrics before making this the default + if (options._experiments.delayFlushOnCheckout) { + // If the full snapshot is due to an initial load, we will not have + // a previous session ID. In this case, we want to buffer events + // for a set amount of time before flushing. This can help avoid + // capturing replays of users that immediately close the window. + setTimeout(() => replay.conditionalFlush(), options._experiments.delayFlushOnCheckout); + + // Cancel any previously debounced flushes to ensure there are no [near] + // simultaneous flushes happening. The latter request should be + // insignificant in this case, so wait for additional user interaction to + // trigger a new flush. + // + // This can happen because there's no guarantee that a recording event + // happens first. e.g. a mouse click can happen and trigger a debounced + // flush before the checkout. + replay.cancelFlush(); + + return true; + } + // Flush immediately so that we do not miss the first segment, otherwise // it can prevent loading on the UI. This will cause an increase in short // replays (e.g. opening and closing a tab quickly), but these can be // filtered on the UI. - // if (replay.recordingMode === 'session') { - // // We want to ensure the worker is ready, as otherwise we'd always send the first event uncompressed - // void replay.flushImmediate(); - // } - - // If the full snapshot is due to an initial load, we will not have - // a previous session ID. In this case, we want to buffer events - // for a set amount of time before flushing. This can help avoid - // capturing replays of users that immediately close the window. - setTimeout(() => replay.conditionalFlush(), replay.getOptions().flushMinDelay); - - // Cancel any previously debounced flushes to ensure there are no [near] - // simultaneous flushes happening. The latter request should be - // insignificant in this case, so wait for additional user interaction to - // trigger a new flush. - // - // This can happen because there's no guarantee that a recording event - // happens first. e.g. a mouse click can happen and trigger a debounced - // flush before the checkout. - replay.cancelFlush(); + if (replay.recordingMode === 'session') { + // We want to ensure the worker is ready, as otherwise we'd always send the first event uncompressed + void replay.flushImmediate(); + } return true; }); diff --git a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts new file mode 100644 index 000000000000..2fcaa72229e4 --- /dev/null +++ b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts @@ -0,0 +1,650 @@ +import { captureException, getCurrentHub } from '@sentry/core'; + +import { + DEFAULT_FLUSH_MIN_DELAY, + ERROR_CHECKOUT_TIME, + MAX_SESSION_LIFE, + REPLAY_SESSION_KEY, + SESSION_IDLE_DURATION, + WINDOW, +} from '../../src/constants'; +import type { ReplayContainer } from '../../src/replay'; +import { addEvent } from '../../src/util/addEvent'; +import { PerformanceEntryResource } from '../fixtures/performanceEntry/resource'; +import type { RecordMock } from '../index'; +import { BASE_TIMESTAMP } from '../index'; +import { resetSdkMock } from '../mocks/resetSdkMock'; +import type { DomHandler } from '../types'; +import { clearSession } from '../utils/clearSession'; +import { useFakeTimers } from '../utils/use-fake-timers'; + +useFakeTimers(); + +async function advanceTimers(time: number) { + jest.advanceTimersByTime(time); + await new Promise(process.nextTick); +} + +describe('Integration | errorSampleRate', () => { + let replay: ReplayContainer; + let mockRecord: RecordMock; + let domHandler: DomHandler; + + beforeEach(async () => { + ({ mockRecord, domHandler, replay } = await resetSdkMock({ + replayOptions: { + stickySession: true, + }, + sentryOptions: { + replaysSessionSampleRate: 0.0, + replaysOnErrorSampleRate: 1.0, + }, + })); + }); + + afterEach(async () => { + clearSession(replay); + replay.stop(); + }); + + it('uploads a replay when `Sentry.captureException` is called and continues recording', async () => { + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + // Does not capture on mouse click + domHandler({ + name: 'click', + }); + jest.runAllTimers(); + await new Promise(process.nextTick); + expect(replay).not.toHaveLastSentReplay(); + + captureException(new Error('testing')); + + await new Promise(process.nextTick); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'error', + contexts: { + replay: { + error_sample_rate: 1, + session_sample_rate: 0, + }, + }, + }), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + TEST_EVENT, + { + type: 5, + timestamp: BASE_TIMESTAMP, + data: { + tag: 'breadcrumb', + payload: { + timestamp: BASE_TIMESTAMP / 1000, + type: 'default', + category: 'ui.click', + message: '', + data: {}, + }, + }, + }, + ]), + }); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + // This is from when we stop recording and start a session recording + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 1 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'error', + contexts: { + replay: { + error_sample_rate: 1, + session_sample_rate: 0, + }, + }, + }), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, type: 2 }, + ]), + }); + + // Check that click will get captured + domHandler({ + name: 'click', + }); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 2 }, + recordingData: JSON.stringify([ + { + type: 5, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80, + data: { + tag: 'breadcrumb', + payload: { + timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80) / 1000, + type: 'default', + category: 'ui.click', + message: '', + data: {}, + }, + }, + }, + ]), + }); + }); + + it('manually flushes replay and does not continue to record', async () => { + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + // Does not capture on mouse click + domHandler({ + name: 'click', + }); + jest.runAllTimers(); + await new Promise(process.nextTick); + expect(replay).not.toHaveLastSentReplay(); + + replay.sendBufferedReplayOrFlush({ continueRecording: false }); + + await new Promise(process.nextTick); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'error', + contexts: { + replay: { + error_sample_rate: 1, + session_sample_rate: 0, + }, + }, + }), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + TEST_EVENT, + { + type: 5, + timestamp: BASE_TIMESTAMP, + data: { + tag: 'breadcrumb', + payload: { + timestamp: BASE_TIMESTAMP / 1000, + type: 'default', + category: 'ui.click', + message: '', + data: {}, + }, + }, + }, + ]), + }); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + // Check that click will not get captured + domHandler({ + name: 'click', + }); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + // This is still the last replay sent since we passed `continueRecording: + // false`. + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'error', + contexts: { + replay: { + error_sample_rate: 1, + session_sample_rate: 0, + }, + }, + }), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + TEST_EVENT, + { + type: 5, + timestamp: BASE_TIMESTAMP, + data: { + tag: 'breadcrumb', + payload: { + timestamp: BASE_TIMESTAMP / 1000, + type: 'default', + category: 'ui.click', + message: '', + data: {}, + }, + }, + }, + ]), + }); + }); + + it('does not send a replay when triggering a full dom snapshot when document becomes visible after [SESSION_IDLE_DURATION]ms', async () => { + Object.defineProperty(document, 'visibilityState', { + configurable: true, + get: function () { + return 'visible'; + }, + }); + + jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + + document.dispatchEvent(new Event('visibilitychange')); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + }); + + it('does not send a replay if user hides the tab and comes back within 60 seconds', async () => { + Object.defineProperty(document, 'visibilityState', { + configurable: true, + get: function () { + return 'hidden'; + }, + }); + document.dispatchEvent(new Event('visibilitychange')); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + + // User comes back before `SESSION_IDLE_DURATION` elapses + jest.advanceTimersByTime(SESSION_IDLE_DURATION - 100); + Object.defineProperty(document, 'visibilityState', { + configurable: true, + get: function () { + return 'visible'; + }, + }); + document.dispatchEvent(new Event('visibilitychange')); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + }); + + it('does not upload a replay event when document becomes hidden', async () => { + Object.defineProperty(document, 'visibilityState', { + configurable: true, + get: function () { + return 'hidden'; + }, + }); + + // Pretend 5 seconds have passed + const ELAPSED = 5000; + jest.advanceTimersByTime(ELAPSED); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 2 }; + addEvent(replay, TEST_EVENT); + + document.dispatchEvent(new Event('visibilitychange')); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + }); + + it('does not upload a replay event if 5 seconds have elapsed since the last replay event occurred', async () => { + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + // Pretend 5 seconds have passed + const ELAPSED = 5000; + await advanceTimers(ELAPSED); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + }); + + it('does not upload a replay event if 15 seconds have elapsed since the last replay upload', async () => { + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + // Fire a new event every 4 seconds, 4 times + [...Array(4)].forEach(() => { + mockRecord._emitter(TEST_EVENT); + jest.advanceTimersByTime(4000); + }); + + // We are at time = +16seconds now (relative to BASE_TIMESTAMP) + // The next event should cause an upload immediately + mockRecord._emitter(TEST_EVENT); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + + // There should also not be another attempt at an upload 5 seconds after the last replay event + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(replay).not.toHaveLastSentReplay(); + + // Let's make sure it continues to work + mockRecord._emitter(TEST_EVENT); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + jest.runAllTimers(); + await new Promise(process.nextTick); + expect(replay).not.toHaveLastSentReplay(); + }); + + // When the error session records as a normal session, we want to stop + // recording after the session ends. Otherwise, we get into a state where the + // new session is a session type replay (this could conflict with the session + // sample rate of 0.0), or an error session that has no errors. Instead we + // simply stop the session replay completely and wait for a new page load to + // resample. + it('stops replay if session exceeds MAX_SESSION_LIFE and does not start a new session thereafter', async () => { + // Idle for 15 minutes + jest.advanceTimersByTime(MAX_SESSION_LIFE + 1); + + const TEST_EVENT = { + data: { name: 'lost event' }, + timestamp: BASE_TIMESTAMP, + type: 3, + }; + mockRecord._emitter(TEST_EVENT); + expect(replay).not.toHaveLastSentReplay(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + // We stop recording after 15 minutes of inactivity in error mode + + expect(replay).not.toHaveLastSentReplay(); + expect(replay.isEnabled()).toBe(false); + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + + domHandler({ + name: 'click', + }); + + // Remains disabled! + expect(replay.isEnabled()).toBe(false); + }); + + // Should behave the same as above test + it('stops replay if user has been idle for more than SESSION_IDLE_DURATION and does not start a new session thereafter', async () => { + // Idle for 15 minutes + jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + + const TEST_EVENT = { + data: { name: 'lost event' }, + timestamp: BASE_TIMESTAMP, + type: 3, + }; + mockRecord._emitter(TEST_EVENT); + expect(replay).not.toHaveLastSentReplay(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + // We stop recording after SESSION_IDLE_DURATION of inactivity in error mode + expect(replay).not.toHaveLastSentReplay(); + expect(replay.isEnabled()).toBe(false); + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + + domHandler({ + name: 'click', + }); + + // Remains disabled! + expect(replay.isEnabled()).toBe(false); + }); + + it('has the correct timestamps with deferred root event and last replay update', async () => { + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + + captureException(new Error('testing')); + + await new Promise(process.nextTick); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveSentReplay({ + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, TEST_EVENT]), + replayEventPayload: expect.objectContaining({ + replay_start_timestamp: BASE_TIMESTAMP / 1000, + // the exception happens roughly 10 seconds after BASE_TIMESTAMP + // (advance timers + waiting for flush after the checkout) and + // extra time is likely due to async of `addMemoryEntry()` + + timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 40) / 1000, + error_ids: [expect.any(String)], + trace_ids: [], + urls: ['http://localhost/'], + replay_id: expect.any(String), + }), + recordingPayloadHeader: { segment_id: 0 }, + }); + }); + + it('has correct timestamps when error occurs much later than initial pageload/checkout', async () => { + const ELAPSED = ERROR_CHECKOUT_TIME; + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + // add a mock performance event + replay.performanceEvents.push(PerformanceEntryResource()); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + jest.advanceTimersByTime(ELAPSED); + + // in production, this happens at a time interval + // session started time should be updated to this current timestamp + mockRecord.takeFullSnapshot(true); + + jest.runAllTimers(); + jest.advanceTimersByTime(20); + await new Promise(process.nextTick); + + captureException(new Error('testing')); + + await new Promise(process.nextTick); + jest.runAllTimers(); + jest.advanceTimersByTime(20); + await new Promise(process.nextTick); + + expect(replay.session?.started).toBe(BASE_TIMESTAMP + ELAPSED + 20); + + // Does not capture mouse click + expect(replay).toHaveSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + // Make sure the old performance event is thrown out + replay_start_timestamp: (BASE_TIMESTAMP + ELAPSED + 20) / 1000, + }), + recordingData: JSON.stringify([ + { + data: { isCheckout: true }, + timestamp: BASE_TIMESTAMP + ELAPSED + 20, + type: 2, + }, + ]), + }); + }); + + it('stops replay when user goes idle', async () => { + jest.setSystemTime(BASE_TIMESTAMP); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + captureException(new Error('testing')); + + await new Promise(process.nextTick); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveLastSentReplay(); + + // Flush from calling `stopRecording` + jest.runAllTimers(); + await new Promise(process.nextTick); + + // Now wait after session expires - should stop recording + mockRecord.takeFullSnapshot.mockClear(); + (getCurrentHub().getClient()!.getTransport()!.send as unknown as jest.SpyInstance).mockClear(); + + expect(replay).not.toHaveLastSentReplay(); + + // Go idle + jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + await new Promise(process.nextTick); + + mockRecord._emitter(TEST_EVENT); + + expect(replay).not.toHaveLastSentReplay(); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0); + expect(replay.isEnabled()).toBe(false); + }); + + it('stops replay when session exceeds max length', async () => { + jest.setSystemTime(BASE_TIMESTAMP); + + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay).not.toHaveLastSentReplay(); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + captureException(new Error('testing')); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveLastSentReplay(); + + // Wait a bit, shortly before session expires + jest.advanceTimersByTime(MAX_SESSION_LIFE - 1000); + await new Promise(process.nextTick); + + mockRecord._emitter(TEST_EVENT); + replay.triggerUserActivity(); + + expect(replay).toHaveLastSentReplay(); + + // Now wait after session expires - should stop recording + mockRecord.takeFullSnapshot.mockClear(); + (getCurrentHub().getClient()!.getTransport()!.send as unknown as jest.SpyInstance).mockClear(); + + jest.advanceTimersByTime(10_000); + await new Promise(process.nextTick); + + mockRecord._emitter(TEST_EVENT); + replay.triggerUserActivity(); + + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).not.toHaveLastSentReplay(); + expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0); + expect(replay.isEnabled()).toBe(false); + }); +}); + +/** + * This is testing a case that should only happen with error-only sessions. + * Previously we had assumed that loading a session from session storage meant + * that the session was not new. However, this is not the case with error-only + * sampling since we can load a saved session that did not have an error (and + * thus no replay was created). + */ +it('sends a replay after loading the session multiple times', async () => { + // Pretend that a session is already saved before loading replay + WINDOW.sessionStorage.setItem( + REPLAY_SESSION_KEY, + `{"segmentId":0,"id":"fd09adfc4117477abc8de643e5a5798a","sampled":"error","started":${BASE_TIMESTAMP},"lastActivity":${BASE_TIMESTAMP}}`, + ); + const { mockRecord, replay } = await resetSdkMock({ + replayOptions: { + stickySession: true, + _experiments: { + delayFlushOnCheckout: DEFAULT_FLUSH_MIN_DELAY + } + }, + autoStart: false, + }); + replay.start(); + + jest.runAllTimers(); + + await new Promise(process.nextTick); + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; + mockRecord._emitter(TEST_EVENT); + + expect(replay).not.toHaveLastSentReplay(); + + captureException(new Error('testing')); + + await new Promise(process.nextTick); + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(replay).toHaveLastSentReplay({ + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, TEST_EVENT]), + }); + + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + // Latest checkout when we call `startRecording` again after uploading segment + // after an error occurs (e.g. when we switch to session replay recording) + expect(replay).toHaveLastSentReplay({ + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 10040, type: 2 }]), + }); +}); From 6b76b93b532d0dcea441cb493d2fef657e8ed990 Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Mon, 1 May 2023 15:32:55 +0200 Subject: [PATCH 4/6] rebase --- .../errorSampleRate-delayFlush.test.ts | 28 +++++++++---------- 1 file changed, 14 insertions(+), 14 deletions(-) diff --git a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts index 2fcaa72229e4..5593467a739b 100644 --- a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts +++ b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts @@ -1,21 +1,21 @@ import { captureException, getCurrentHub } from '@sentry/core'; import { + BUFFER_CHECKOUT_TIME, DEFAULT_FLUSH_MIN_DELAY, - ERROR_CHECKOUT_TIME, MAX_SESSION_LIFE, REPLAY_SESSION_KEY, - SESSION_IDLE_DURATION, + SESSION_IDLE_EXPIRE_DURATION, WINDOW, } from '../../src/constants'; import type { ReplayContainer } from '../../src/replay'; +import { clearSession } from '../../src/session/clearSession'; import { addEvent } from '../../src/util/addEvent'; import { PerformanceEntryResource } from '../fixtures/performanceEntry/resource'; import type { RecordMock } from '../index'; import { BASE_TIMESTAMP } from '../index'; import { resetSdkMock } from '../mocks/resetSdkMock'; import type { DomHandler } from '../types'; -import { clearSession } from '../utils/clearSession'; import { useFakeTimers } from '../utils/use-fake-timers'; useFakeTimers(); @@ -242,7 +242,7 @@ describe('Integration | errorSampleRate', () => { }); }); - it('does not send a replay when triggering a full dom snapshot when document becomes visible after [SESSION_IDLE_DURATION]ms', async () => { + it('does not send a replay when triggering a full dom snapshot when document becomes visible after [SESSION_IDLE_EXPIRE_DURATION]ms', async () => { Object.defineProperty(document, 'visibilityState', { configurable: true, get: function () { @@ -250,7 +250,7 @@ describe('Integration | errorSampleRate', () => { }, }); - jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + jest.advanceTimersByTime(SESSION_IDLE_EXPIRE_DURATION + 1); document.dispatchEvent(new Event('visibilitychange')); @@ -274,8 +274,8 @@ describe('Integration | errorSampleRate', () => { expect(replay).not.toHaveLastSentReplay(); - // User comes back before `SESSION_IDLE_DURATION` elapses - jest.advanceTimersByTime(SESSION_IDLE_DURATION - 100); + // User comes back before `SESSION_IDLE_EXPIRE_DURATION` elapses + jest.advanceTimersByTime(SESSION_IDLE_EXPIRE_DURATION - 100); Object.defineProperty(document, 'visibilityState', { configurable: true, get: function () { @@ -393,9 +393,9 @@ describe('Integration | errorSampleRate', () => { }); // Should behave the same as above test - it('stops replay if user has been idle for more than SESSION_IDLE_DURATION and does not start a new session thereafter', async () => { + it('stops replay if user has been idle for more than SESSION_IDLE_EXPIRE_DURATION and does not start a new session thereafter', async () => { // Idle for 15 minutes - jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + jest.advanceTimersByTime(SESSION_IDLE_EXPIRE_DURATION + 1); const TEST_EVENT = { data: { name: 'lost event' }, @@ -408,7 +408,7 @@ describe('Integration | errorSampleRate', () => { jest.runAllTimers(); await new Promise(process.nextTick); - // We stop recording after SESSION_IDLE_DURATION of inactivity in error mode + // We stop recording after SESSION_IDLE_EXPIRE_DURATION of inactivity in error mode expect(replay).not.toHaveLastSentReplay(); expect(replay.isEnabled()).toBe(false); expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); @@ -458,7 +458,7 @@ describe('Integration | errorSampleRate', () => { }); it('has correct timestamps when error occurs much later than initial pageload/checkout', async () => { - const ELAPSED = ERROR_CHECKOUT_TIME; + const ELAPSED = BUFFER_CHECKOUT_TIME; const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; mockRecord._emitter(TEST_EVENT); @@ -538,7 +538,7 @@ describe('Integration | errorSampleRate', () => { expect(replay).not.toHaveLastSentReplay(); // Go idle - jest.advanceTimersByTime(SESSION_IDLE_DURATION + 1); + jest.advanceTimersByTime(SESSION_IDLE_EXPIRE_DURATION + 1); await new Promise(process.nextTick); mockRecord._emitter(TEST_EVENT); @@ -617,8 +617,8 @@ it('sends a replay after loading the session multiple times', async () => { replayOptions: { stickySession: true, _experiments: { - delayFlushOnCheckout: DEFAULT_FLUSH_MIN_DELAY - } + delayFlushOnCheckout: DEFAULT_FLUSH_MIN_DELAY, + }, }, autoStart: false, }); From aab478669edca1bffd79c2499a752ddd7dea2bce Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Tue, 2 May 2023 10:47:52 +0200 Subject: [PATCH 5/6] fix tests --- .../errorSampleRate-delayFlush.test.ts | 238 +++++++++++++----- 1 file changed, 176 insertions(+), 62 deletions(-) diff --git a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts index 5593467a739b..ccfb5ae738d4 100644 --- a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts +++ b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts @@ -25,7 +25,16 @@ async function advanceTimers(time: number) { await new Promise(process.nextTick); } -describe('Integration | errorSampleRate', () => { +async function waitForBufferFlush() { + await new Promise(process.nextTick); + await new Promise(process.nextTick); +} + +async function waitForFlush() { + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); +} + +describe('Integration | errorSampleRate with delayed flush', () => { let replay: ReplayContainer; let mockRecord: RecordMock; let domHandler: DomHandler; @@ -34,6 +43,9 @@ describe('Integration | errorSampleRate', () => { ({ mockRecord, domHandler, replay } = await resetSdkMock({ replayOptions: { stickySession: true, + _experiments: { + delayFlushOnCheckout: DEFAULT_FLUSH_MIN_DELAY, + }, }, sentryOptions: { replaysSessionSampleRate: 0.0, @@ -64,14 +76,12 @@ describe('Integration | errorSampleRate', () => { captureException(new Error('testing')); - await new Promise(process.nextTick); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForBufferFlush(); - expect(replay).toHaveSentReplay({ + expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ - replay_type: 'error', + replay_type: 'buffer', contexts: { replay: { error_sample_rate: 1, @@ -99,14 +109,13 @@ describe('Integration | errorSampleRate', () => { ]), }); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForFlush(); // This is from when we stop recording and start a session recording expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 1 }, replayEventPayload: expect.objectContaining({ - replay_type: 'error', + replay_type: 'buffer', contexts: { replay: { error_sample_rate: 1, @@ -114,29 +123,27 @@ describe('Integration | errorSampleRate', () => { }, }, }), - recordingData: JSON.stringify([ - { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, type: 2 }, - ]), + recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 40, type: 2 }]), }); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + // Check that click will get captured domHandler({ name: 'click', }); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForFlush(); expect(replay).toHaveLastSentReplay({ - recordingPayloadHeader: { segment_id: 2 }, recordingData: JSON.stringify([ { type: 5, - timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80, + timestamp: BASE_TIMESTAMP + 10000 + 80, data: { tag: 'breadcrumb', payload: { - timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + DEFAULT_FLUSH_MIN_DELAY + 80) / 1000, + timestamp: (BASE_TIMESTAMP + 10000 + 80) / 1000, type: 'default', category: 'ui.click', message: '', @@ -165,14 +172,12 @@ describe('Integration | errorSampleRate', () => { replay.sendBufferedReplayOrFlush({ continueRecording: false }); - await new Promise(process.nextTick); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForBufferFlush(); expect(replay).toHaveSentReplay({ recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ - replay_type: 'error', + replay_type: 'buffer', contexts: { replay: { error_sample_rate: 1, @@ -205,15 +210,15 @@ describe('Integration | errorSampleRate', () => { domHandler({ name: 'click', }); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + + await waitForFlush(); // This is still the last replay sent since we passed `continueRecording: // false`. expect(replay).toHaveLastSentReplay({ recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ - replay_type: 'error', + replay_type: 'buffer', contexts: { replay: { error_sample_rate: 1, @@ -346,12 +351,12 @@ describe('Integration | errorSampleRate', () => { expect(replay).not.toHaveLastSentReplay(); // There should also not be another attempt at an upload 5 seconds after the last replay event - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + await waitForFlush(); expect(replay).not.toHaveLastSentReplay(); // Let's make sure it continues to work mockRecord._emitter(TEST_EVENT); - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + await waitForFlush(); jest.runAllTimers(); await new Promise(process.nextTick); expect(replay).not.toHaveLastSentReplay(); @@ -363,9 +368,80 @@ describe('Integration | errorSampleRate', () => { // sample rate of 0.0), or an error session that has no errors. Instead we // simply stop the session replay completely and wait for a new page load to // resample. - it('stops replay if session exceeds MAX_SESSION_LIFE and does not start a new session thereafter', async () => { - // Idle for 15 minutes - jest.advanceTimersByTime(MAX_SESSION_LIFE + 1); + it.each([ + ['MAX_SESSION_LIFE', MAX_SESSION_LIFE], + ['SESSION_IDLE_DURATION', SESSION_IDLE_EXPIRE_DURATION], + ])( + 'stops replay if session had an error and exceeds %s and does not start a new session thereafter', + async (_label, waitTime) => { + expect(replay.session?.shouldRefresh).toBe(true); + + captureException(new Error('testing')); + + await waitForBufferFlush(); + + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'buffer', + }), + }); + + await waitForFlush(); + + // segment_id is 1 because it sends twice on error + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 1 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'buffer', + }), + }); + expect(replay.session?.shouldRefresh).toBe(false); + + // Idle for given time + jest.advanceTimersByTime(waitTime + 1); + await new Promise(process.nextTick); + + const TEST_EVENT = { + data: { name: 'lost event' }, + timestamp: BASE_TIMESTAMP, + type: 3, + }; + mockRecord._emitter(TEST_EVENT); + + jest.runAllTimers(); + await new Promise(process.nextTick); + + // We stop recording after 15 minutes of inactivity in error mode + + // still no new replay sent + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 1 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'buffer', + }), + }); + + expect(replay.isEnabled()).toBe(false); + + domHandler({ + name: 'click', + }); + + // Remains disabled! + expect(replay.isEnabled()).toBe(false); + }, + ); + + it.each([ + ['MAX_SESSION_LIFE', MAX_SESSION_LIFE], + ['SESSION_IDLE_EXPIRE_DURATION', SESSION_IDLE_EXPIRE_DURATION], + ])('continues buffering replay if session had no error and exceeds %s', async (_label, waitTime) => { + expect(replay).not.toHaveLastSentReplay(); + + // Idle for given time + jest.advanceTimersByTime(waitTime + 1); + await new Promise(process.nextTick); const TEST_EVENT = { data: { name: 'lost event' }, @@ -373,23 +449,45 @@ describe('Integration | errorSampleRate', () => { type: 3, }; mockRecord._emitter(TEST_EVENT); - expect(replay).not.toHaveLastSentReplay(); jest.runAllTimers(); await new Promise(process.nextTick); - // We stop recording after 15 minutes of inactivity in error mode - + // still no new replay sent expect(replay).not.toHaveLastSentReplay(); - expect(replay.isEnabled()).toBe(false); - expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('buffer'); domHandler({ name: 'click', }); - // Remains disabled! - expect(replay.isEnabled()).toBe(false); + await waitForFlush(); + + expect(replay).not.toHaveLastSentReplay(); + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('buffer'); + + // should still react to errors later on + captureException(new Error('testing')); + + await waitForBufferFlush(); + + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'buffer', + }), + }); + + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('session'); + expect(replay.session?.sampled).toBe('buffer'); + expect(replay.session?.shouldRefresh).toBe(false); }); // Should behave the same as above test @@ -410,15 +508,29 @@ describe('Integration | errorSampleRate', () => { // We stop recording after SESSION_IDLE_EXPIRE_DURATION of inactivity in error mode expect(replay).not.toHaveLastSentReplay(); - expect(replay.isEnabled()).toBe(false); - expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('buffer'); - domHandler({ - name: 'click', + // should still react to errors later on + captureException(new Error('testing')); + + await new Promise(process.nextTick); + jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); + await new Promise(process.nextTick); + + expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 0 }, + replayEventPayload: expect.objectContaining({ + replay_type: 'buffer', + }), }); - // Remains disabled! - expect(replay.isEnabled()).toBe(false); + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('session'); + expect(replay.session?.sampled).toBe('buffer'); + expect(replay.session?.shouldRefresh).toBe(false); }); it('has the correct timestamps with deferred root event and last replay update', async () => { @@ -483,10 +595,7 @@ describe('Integration | errorSampleRate', () => { captureException(new Error('testing')); - await new Promise(process.nextTick); - jest.runAllTimers(); - jest.advanceTimersByTime(20); - await new Promise(process.nextTick); + await waitForBufferFlush(); expect(replay.session?.started).toBe(BASE_TIMESTAMP + ELAPSED + 20); @@ -521,15 +630,12 @@ describe('Integration | errorSampleRate', () => { captureException(new Error('testing')); - await new Promise(process.nextTick); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForBufferFlush(); expect(replay).toHaveLastSentReplay(); // Flush from calling `stopRecording` - jest.runAllTimers(); - await new Promise(process.nextTick); + await waitForFlush(); // Now wait after session expires - should stop recording mockRecord.takeFullSnapshot.mockClear(); @@ -545,8 +651,7 @@ describe('Integration | errorSampleRate', () => { expect(replay).not.toHaveLastSentReplay(); - jest.advanceTimersByTime(DEFAULT_FLUSH_MIN_DELAY); - await new Promise(process.nextTick); + await waitForFlush(); expect(replay).not.toHaveLastSentReplay(); expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0); @@ -607,22 +712,26 @@ describe('Integration | errorSampleRate', () => { * sampling since we can load a saved session that did not have an error (and * thus no replay was created). */ -it('sends a replay after loading the session multiple times', async () => { +it('sends a replay after loading the session from storage', async () => { // Pretend that a session is already saved before loading replay WINDOW.sessionStorage.setItem( REPLAY_SESSION_KEY, - `{"segmentId":0,"id":"fd09adfc4117477abc8de643e5a5798a","sampled":"error","started":${BASE_TIMESTAMP},"lastActivity":${BASE_TIMESTAMP}}`, + `{"segmentId":0,"id":"fd09adfc4117477abc8de643e5a5798a","sampled":"buffer","started":${BASE_TIMESTAMP},"lastActivity":${BASE_TIMESTAMP}}`, ); - const { mockRecord, replay } = await resetSdkMock({ + const { mockRecord, replay, integration } = await resetSdkMock({ replayOptions: { stickySession: true, _experiments: { delayFlushOnCheckout: DEFAULT_FLUSH_MIN_DELAY, }, }, + sentryOptions: { + replaysOnErrorSampleRate: 1.0, + }, autoStart: false, }); - replay.start(); + // @ts-ignore this is protected, but we want to call it for this test + integration._initialize(); jest.runAllTimers(); @@ -634,17 +743,22 @@ it('sends a replay after loading the session multiple times', async () => { captureException(new Error('testing')); - await new Promise(process.nextTick); - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + // 2 ticks to send replay from an error + await waitForBufferFlush(); - expect(replay).toHaveLastSentReplay({ + // Buffered events before error + expect(replay).toHaveSentReplay({ recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, TEST_EVENT]), }); - await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + // `startRecording()` after switching to session mode to continue recording + await waitForFlush(); + // Latest checkout when we call `startRecording` again after uploading segment // after an error occurs (e.g. when we switch to session replay recording) expect(replay).toHaveLastSentReplay({ - recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 10040, type: 2 }]), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, type: 2 }, + ]), }); }); From 541045311722bd9544f6a50c80208fc217143f00 Mon Sep 17 00:00:00 2001 From: Billy Vong Date: Mon, 15 May 2023 14:12:55 -0400 Subject: [PATCH 6/6] fix tests --- .../errorSampleRate-delayFlush.test.ts | 51 +++++++++---------- 1 file changed, 23 insertions(+), 28 deletions(-) diff --git a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts index ccfb5ae738d4..c0b711c028f8 100644 --- a/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts +++ b/packages/replay/test/integration/errorSampleRate-delayFlush.test.ts @@ -11,6 +11,7 @@ import { import type { ReplayContainer } from '../../src/replay'; import { clearSession } from '../../src/session/clearSession'; import { addEvent } from '../../src/util/addEvent'; +import { createOptionsEvent } from '../../src/util/handleRecordingEmit'; import { PerformanceEntryResource } from '../fixtures/performanceEntry/resource'; import type { RecordMock } from '../index'; import { BASE_TIMESTAMP } from '../index'; @@ -62,6 +63,7 @@ describe('Integration | errorSampleRate with delayed flush', () => { it('uploads a replay when `Sentry.captureException` is called and continues recording', async () => { const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; mockRecord._emitter(TEST_EVENT); + const optionsEvent = createOptionsEvent(replay); expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); expect(replay).not.toHaveLastSentReplay(); @@ -82,15 +84,10 @@ describe('Integration | errorSampleRate with delayed flush', () => { recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ replay_type: 'buffer', - contexts: { - replay: { - error_sample_rate: 1, - session_sample_rate: 0, - }, - }, }), recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + optionsEvent, TEST_EVENT, { type: 5, @@ -116,12 +113,6 @@ describe('Integration | errorSampleRate with delayed flush', () => { recordingPayloadHeader: { segment_id: 1 }, replayEventPayload: expect.objectContaining({ replay_type: 'buffer', - contexts: { - replay: { - error_sample_rate: 1, - session_sample_rate: 0, - }, - }, }), recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + 40, type: 2 }]), }); @@ -158,6 +149,7 @@ describe('Integration | errorSampleRate with delayed flush', () => { it('manually flushes replay and does not continue to record', async () => { const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; mockRecord._emitter(TEST_EVENT); + const optionsEvent = createOptionsEvent(replay); expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); expect(replay).not.toHaveLastSentReplay(); @@ -178,15 +170,10 @@ describe('Integration | errorSampleRate with delayed flush', () => { recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ replay_type: 'buffer', - contexts: { - replay: { - error_sample_rate: 1, - session_sample_rate: 0, - }, - }, }), recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + optionsEvent, TEST_EVENT, { type: 5, @@ -219,15 +206,10 @@ describe('Integration | errorSampleRate with delayed flush', () => { recordingPayloadHeader: { segment_id: 0 }, replayEventPayload: expect.objectContaining({ replay_type: 'buffer', - contexts: { - replay: { - error_sample_rate: 1, - session_sample_rate: 0, - }, - }, }), recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + optionsEvent, TEST_EVENT, { type: 5, @@ -536,6 +518,7 @@ describe('Integration | errorSampleRate with delayed flush', () => { it('has the correct timestamps with deferred root event and last replay update', async () => { const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP, type: 3 }; mockRecord._emitter(TEST_EVENT); + const optionsEvent = createOptionsEvent(replay); expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled(); expect(replay).not.toHaveLastSentReplay(); @@ -552,7 +535,11 @@ describe('Integration | errorSampleRate with delayed flush', () => { await new Promise(process.nextTick); expect(replay).toHaveSentReplay({ - recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, TEST_EVENT]), + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + optionsEvent, + TEST_EVENT, + ]), replayEventPayload: expect.objectContaining({ replay_start_timestamp: BASE_TIMESTAMP / 1000, // the exception happens roughly 10 seconds after BASE_TIMESTAMP @@ -588,6 +575,7 @@ describe('Integration | errorSampleRate with delayed flush', () => { // in production, this happens at a time interval // session started time should be updated to this current timestamp mockRecord.takeFullSnapshot(true); + const optionsEvent = createOptionsEvent(replay); jest.runAllTimers(); jest.advanceTimersByTime(20); @@ -612,6 +600,7 @@ describe('Integration | errorSampleRate with delayed flush', () => { timestamp: BASE_TIMESTAMP + ELAPSED + 20, type: 2, }, + optionsEvent, ]), }); }); @@ -730,8 +719,8 @@ it('sends a replay after loading the session from storage', async () => { }, autoStart: false, }); - // @ts-ignore this is protected, but we want to call it for this test - integration._initialize(); + integration['_initialize'](); + const optionsEvent = createOptionsEvent(replay); jest.runAllTimers(); @@ -748,7 +737,12 @@ it('sends a replay after loading the session from storage', async () => { // Buffered events before error expect(replay).toHaveSentReplay({ - recordingData: JSON.stringify([{ data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, TEST_EVENT]), + recordingPayloadHeader: { segment_id: 0 }, + recordingData: JSON.stringify([ + { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP, type: 2 }, + optionsEvent, + TEST_EVENT, + ]), }); // `startRecording()` after switching to session mode to continue recording @@ -757,6 +751,7 @@ it('sends a replay after loading the session from storage', async () => { // Latest checkout when we call `startRecording` again after uploading segment // after an error occurs (e.g. when we switch to session replay recording) expect(replay).toHaveLastSentReplay({ + recordingPayloadHeader: { segment_id: 1 }, recordingData: JSON.stringify([ { data: { isCheckout: true }, timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY + 40, type: 2 }, ]),