From a425cad45c4f390b12dd1cdc49f6e399f0ac5737 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Wed, 9 Aug 2023 13:35:05 +0200 Subject: [PATCH] ref(replay): Skip events being added too long after initial segment --- packages/replay/src/util/addEvent.ts | 10 ++++ .../test/integration/errorSampleRate.test.ts | 44 ++++++++++++++ .../replay/test/integration/flush.test.ts | 60 +++++++++++++++++++ 3 files changed, 114 insertions(+) diff --git a/packages/replay/src/util/addEvent.ts b/packages/replay/src/util/addEvent.ts index d1e1d366a9e9..6ffd5d03bacd 100644 --- a/packages/replay/src/util/addEvent.ts +++ b/packages/replay/src/util/addEvent.ts @@ -4,6 +4,7 @@ import { logger } from '@sentry/utils'; import { EventBufferSizeExceededError } from '../eventBuffer/error'; import type { AddEventResult, RecordingEvent, ReplayContainer, ReplayFrameEvent, ReplayPluginOptions } from '../types'; +import { logInfo } from './log'; import { timestampToMs } from './timestamp'; function isCustomEvent(event: RecordingEvent): event is ReplayFrameEvent { @@ -39,6 +40,15 @@ export async function addEvent( return null; } + // Throw out events that are +60min from the initial timestamp + if (timestampInMs > replay.getContext().initialTimestamp + replay.timeouts.maxSessionLife) { + logInfo( + `[Replay] Skipping event with timestamp ${timestampInMs} because it is after maxSessionLife`, + replay.getOptions()._experiments.traceInternals, + ); + return null; + } + try { if (isCheckout && replay.recordingMode === 'buffer') { replay.eventBuffer.clear(); diff --git a/packages/replay/test/integration/errorSampleRate.test.ts b/packages/replay/test/integration/errorSampleRate.test.ts index 7ed9c4774c71..777cb437f7e3 100644 --- a/packages/replay/test/integration/errorSampleRate.test.ts +++ b/packages/replay/test/integration/errorSampleRate.test.ts @@ -883,6 +883,50 @@ describe('Integration | errorSampleRate', () => { expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0); expect(replay.isEnabled()).toBe(false); }); + + it('handles very long active buffer session', async () => { + const stepDuration = 10_000; + const steps = 5_000; + + jest.setSystemTime(BASE_TIMESTAMP); + + expect(replay).not.toHaveLastSentReplay(); + + let optionsEvent = createOptionsEvent(replay); + + for (let i = 1; i <= steps; i++) { + jest.advanceTimersByTime(stepDuration); + optionsEvent = createOptionsEvent(replay); + mockRecord._emitter({ data: { step: i }, timestamp: BASE_TIMESTAMP + stepDuration * i, type: 2 }, true); + mockRecord._emitter({ data: { step: i }, timestamp: BASE_TIMESTAMP + stepDuration * i + 5, type: 3 }); + } + + expect(replay).not.toHaveLastSentReplay(); + + expect(replay.isEnabled()).toBe(true); + expect(replay.isPaused()).toBe(false); + expect(replay.recordingMode).toBe('buffer'); + + // Now capture an error + captureException(new Error('testing')); + await waitForBufferFlush(); + + expect(replay).toHaveLastSentReplay({ + recordingData: JSON.stringify([ + { data: { step: steps }, timestamp: BASE_TIMESTAMP + stepDuration * steps, type: 2 }, + optionsEvent, + { data: { step: steps }, timestamp: BASE_TIMESTAMP + stepDuration * steps + 5, type: 3 }, + ]), + replayEventPayload: expect.objectContaining({ + replay_start_timestamp: (BASE_TIMESTAMP + stepDuration * steps) / 1000, + error_ids: [expect.any(String)], + trace_ids: [], + urls: ['http://localhost/'], + replay_id: expect.any(String), + }), + recordingPayloadHeader: { segment_id: 0 }, + }); + }); }); /** diff --git a/packages/replay/test/integration/flush.test.ts b/packages/replay/test/integration/flush.test.ts index 611a1043df1a..6e6e02d86620 100644 --- a/packages/replay/test/integration/flush.test.ts +++ b/packages/replay/test/integration/flush.test.ts @@ -26,6 +26,7 @@ type MockFlush = jest.MockedFunction; type MockRunFlush = jest.MockedFunction; const prevLocation = WINDOW.location; +const prevBrowserPerformanceTimeOrigin = SentryUtils.browserPerformanceTimeOrigin; describe('Integration | flush', () => { let domHandler: (args: any) => any; @@ -91,6 +92,11 @@ describe('Integration | flush', () => { } mockEventBufferFinish = replay.eventBuffer?.finish as MockEventBufferFinish; mockEventBufferFinish.mockClear(); + + Object.defineProperty(SentryUtils, 'browserPerformanceTimeOrigin', { + value: BASE_TIMESTAMP, + writable: true, + }); }); afterEach(async () => { @@ -102,6 +108,10 @@ describe('Integration | flush', () => { value: prevLocation, writable: true, }); + Object.defineProperty(SentryUtils, 'browserPerformanceTimeOrigin', { + value: prevBrowserPerformanceTimeOrigin, + writable: true, + }); }); afterAll(() => { @@ -224,6 +234,7 @@ describe('Integration | flush', () => { // flush #5 @ t=25s - debounced flush calls `flush` // 20s + `flushMinDelay` which is 5 seconds await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(mockFlush).toHaveBeenCalledTimes(5); expect(mockRunFlush).toHaveBeenCalledTimes(2); expect(mockSendReplay).toHaveBeenLastCalledWith({ @@ -382,4 +393,53 @@ describe('Integration | flush', () => { replay.getOptions()._experiments.traceInternals = false; }); + + it('logs warning if adding event that is after maxSessionLife', async () => { + replay.getOptions()._experiments.traceInternals = true; + + sessionStorage.clear(); + clearSession(replay); + replay['_loadAndCheckSession'](); + await new Promise(process.nextTick); + jest.setSystemTime(BASE_TIMESTAMP); + + replay.eventBuffer!.clear(); + + // We do not care about this warning here + replay.eventBuffer!.hasCheckout = true; + + // Add event that is too long after session start + const TEST_EVENT = { data: {}, timestamp: BASE_TIMESTAMP + MAX_SESSION_LIFE + 100, type: 2 }; + mockRecord._emitter(TEST_EVENT); + + // no checkout! + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(mockFlush).toHaveBeenCalledTimes(1); + expect(mockSendReplay).toHaveBeenCalledTimes(1); + + const replayData = mockSendReplay.mock.calls[0][0]; + + expect(JSON.parse(replayData.recordingData)).toEqual([ + { + type: 5, + timestamp: BASE_TIMESTAMP, + data: { + tag: 'breadcrumb', + payload: { + timestamp: BASE_TIMESTAMP / 1000, + type: 'default', + category: 'console', + data: { logger: 'replay' }, + level: 'info', + message: `[Replay] Skipping event with timestamp ${ + BASE_TIMESTAMP + MAX_SESSION_LIFE + 100 + } because it is after maxSessionLife`, + }, + }, + }, + ]); + + replay.getOptions()._experiments.traceInternals = false; + }); });