From b2f5c860ee6d3ebc2e574eb4d41f12b042b08372 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Mon, 7 Aug 2023 17:14:40 +0200 Subject: [PATCH 1/2] ref(replay): Log warning if trying to flush initial segment without checkout We keep track of the eventBuffer contains a checkout, and if not, log a warning when trying to flush the initial segment. If this turns out to be happening, we may think about aborting flushing or similar in this case. But for now, we can gather data. --- .../src/eventBuffer/EventBufferArray.ts | 6 ++ .../EventBufferCompressionWorker.ts | 6 ++ .../src/eventBuffer/EventBufferProxy.ts | 9 +++ packages/replay/src/replay.ts | 6 ++ packages/replay/src/types/replay.ts | 5 ++ packages/replay/src/util/addEvent.ts | 1 + .../replay/test/integration/flush.test.ts | 74 ++++++++++++++++++- 7 files changed, 105 insertions(+), 2 deletions(-) diff --git a/packages/replay/src/eventBuffer/EventBufferArray.ts b/packages/replay/src/eventBuffer/EventBufferArray.ts index c9915e7c8b05..2eb760409d9f 100644 --- a/packages/replay/src/eventBuffer/EventBufferArray.ts +++ b/packages/replay/src/eventBuffer/EventBufferArray.ts @@ -10,11 +10,16 @@ import { EventBufferSizeExceededError } from './error'; export class EventBufferArray implements EventBuffer { /** All the events that are buffered to be sent. */ public events: RecordingEvent[]; + + /** @inheritdoc */ + public hasCheckout: boolean; + private _totalSize: number; public constructor() { this.events = []; this._totalSize = 0; + this.hasCheckout = false; } /** @inheritdoc */ @@ -59,6 +64,7 @@ export class EventBufferArray implements EventBuffer { public clear(): void { this.events = []; this._totalSize = 0; + this.hasCheckout = false; } /** @inheritdoc */ diff --git a/packages/replay/src/eventBuffer/EventBufferCompressionWorker.ts b/packages/replay/src/eventBuffer/EventBufferCompressionWorker.ts index 8c40c5d289cf..90e1eeba8f11 100644 --- a/packages/replay/src/eventBuffer/EventBufferCompressionWorker.ts +++ b/packages/replay/src/eventBuffer/EventBufferCompressionWorker.ts @@ -11,6 +11,9 @@ import { WorkerHandler } from './WorkerHandler'; * Exported only for testing. */ export class EventBufferCompressionWorker implements EventBuffer { + /** @inheritdoc */ + public hasCheckout: boolean; + private _worker: WorkerHandler; private _earliestTimestamp: number | null; private _totalSize; @@ -19,6 +22,7 @@ export class EventBufferCompressionWorker implements EventBuffer { this._worker = new WorkerHandler(worker); this._earliestTimestamp = null; this._totalSize = 0; + this.hasCheckout = false; } /** @inheritdoc */ @@ -78,6 +82,8 @@ export class EventBufferCompressionWorker implements EventBuffer { public clear(): void { this._earliestTimestamp = null; this._totalSize = 0; + this.hasCheckout = false; + // We do not wait on this, as we assume the order of messages is consistent for the worker void this._worker.postMessage('clear'); } diff --git a/packages/replay/src/eventBuffer/EventBufferProxy.ts b/packages/replay/src/eventBuffer/EventBufferProxy.ts index 2b3c2329f876..0b5a6bdfed11 100644 --- a/packages/replay/src/eventBuffer/EventBufferProxy.ts +++ b/packages/replay/src/eventBuffer/EventBufferProxy.ts @@ -35,6 +35,15 @@ export class EventBufferProxy implements EventBuffer { return this._used.hasEvents; } + /** @inheritdoc */ + public get hasCheckout(): boolean { + return this._used.hasCheckout; + } + /** @inheritdoc */ + public set hasCheckout(value: boolean) { + this._used.hasCheckout = value; + } + /** @inheritDoc */ public destroy(): void { this._fallback.destroy(); diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index c66d1d914d82..f6bce8fdf216 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -1151,6 +1151,12 @@ export class ReplayContainer implements ReplayContainerInterface { return; } + const eventBuffer = this.eventBuffer; + if (eventBuffer && this.session.segmentId === 0 && !eventBuffer.hasCheckout) { + logInfo('[Replay] Flushing initial segment without checkout.', this._options._experiments.traceInternals); + // TODO FN: Evaluate if we want to stop here, or remove this again? + } + // this._flushLock acts as a lock so that future calls to `_flush()` // will be blocked until this promise resolves if (!this._flushLock) { diff --git a/packages/replay/src/types/replay.ts b/packages/replay/src/types/replay.ts index 46f1e8f4ef93..1fbf44aa1b95 100644 --- a/packages/replay/src/types/replay.ts +++ b/packages/replay/src/types/replay.ts @@ -389,6 +389,11 @@ export interface EventBuffer { */ readonly type: EventBufferType; + /** + * If the event buffer contains a checkout event. + */ + hasCheckout: boolean; + /** * Destroy the event buffer. */ diff --git a/packages/replay/src/util/addEvent.ts b/packages/replay/src/util/addEvent.ts index 4718675700a9..d1e1d366a9e9 100644 --- a/packages/replay/src/util/addEvent.ts +++ b/packages/replay/src/util/addEvent.ts @@ -42,6 +42,7 @@ export async function addEvent( try { if (isCheckout && replay.recordingMode === 'buffer') { replay.eventBuffer.clear(); + replay.eventBuffer.hasCheckout = true; } const replayOptions = replay.getOptions(); diff --git a/packages/replay/test/integration/flush.test.ts b/packages/replay/test/integration/flush.test.ts index a4fbdb464ae4..2ebd0dcc6923 100644 --- a/packages/replay/test/integration/flush.test.ts +++ b/packages/replay/test/integration/flush.test.ts @@ -1,6 +1,6 @@ import * as SentryUtils from '@sentry/utils'; -import { DEFAULT_FLUSH_MIN_DELAY, WINDOW } from '../../src/constants'; +import { DEFAULT_FLUSH_MIN_DELAY, MAX_SESSION_LIFE, WINDOW } from '../../src/constants'; import type { ReplayContainer } from '../../src/replay'; import { clearSession } from '../../src/session/clearSession'; import type { EventBuffer } from '../../src/types'; @@ -286,15 +286,22 @@ describe('Integration | flush', () => { expect(mockFlush).toHaveBeenCalledTimes(20); expect(mockSendReplay).toHaveBeenCalledTimes(1); + + replay.getOptions().minReplayDuration = 0; }); it('does not flush if session is too long', async () => { replay.timeouts.maxSessionLife = 100_000; - jest.setSystemTime(new Date(BASE_TIMESTAMP)); + jest.setSystemTime(BASE_TIMESTAMP); sessionStorage.clear(); clearSession(replay); replay['_loadAndCheckSession'](); + // No-op _loadAndCheckSession to avoid us resetting the session for this test + const _tmp = replay['_loadAndCheckSession']; + replay['_loadAndCheckSession'] = () => { + return true; + }; await advanceTimers(120_000); @@ -308,7 +315,70 @@ describe('Integration | flush', () => { mockRecord._emitter(TEST_EVENT); await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + expect(mockFlush).toHaveBeenCalledTimes(1); expect(mockSendReplay).toHaveBeenCalledTimes(0); + + replay.timeouts.maxSessionLife = MAX_SESSION_LIFE; + replay['_loadAndCheckSession'] = _tmp; + }); + + it('logs warning if flushing initial segment without checkout', async () => { + replay.getOptions()._experiments.traceInternals = true; + + sessionStorage.clear(); + clearSession(replay); + replay['_loadAndCheckSession'](); + + // Clear the event buffer to simulate no checkout happened + replay.eventBuffer!.clear(); + + // click happens first + domHandler({ + name: 'click', + }); + + // no checkout! + await advanceTimers(DEFAULT_FLUSH_MIN_DELAY); + + expect(mockFlush).toHaveBeenCalledTimes(1); + expect(mockSendReplay).toHaveBeenCalledTimes(1); + expect(mockSendReplay).toHaveBeenLastCalledWith( + expect.objectContaining({ + recordingData: JSON.stringify([ + { + type: 5, + timestamp: BASE_TIMESTAMP, + data: { + tag: 'breadcrumb', + payload: { + timestamp: BASE_TIMESTAMP / 1000, + type: 'default', + category: 'ui.click', + message: '', + data: {}, + }, + }, + }, + { + type: 5, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, + data: { + tag: 'breadcrumb', + payload: { + timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY) / 1000, + type: 'default', + category: 'console', + data: { logger: 'replay' }, + level: 'info', + message: '[Replay] Flushing initial segment without checkout.', + }, + }, + }, + ]), + }), + ); + + replay.getOptions()._experiments.traceInternals = false; }); }); From 14f47b57d74dc12e1511c62d3c3fe8174e42ac3d Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 8 Aug 2023 10:27:04 +0200 Subject: [PATCH 2/2] ref: Fix PR & logging --- packages/replay/src/replay.ts | 11 +-- packages/replay/src/session/fetchSession.ts | 4 +- packages/replay/src/session/getSession.ts | 8 +-- packages/replay/src/util/log.ts | 44 ++++++++---- .../replay/test/integration/flush.test.ts | 67 ++++++++++--------- 5 files changed, 79 insertions(+), 55 deletions(-) diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts index f6bce8fdf216..dd82e26f3d57 100644 --- a/packages/replay/src/replay.ts +++ b/packages/replay/src/replay.ts @@ -47,7 +47,7 @@ import { debounce } from './util/debounce'; import { getHandleRecordingEmit } from './util/handleRecordingEmit'; import { isExpired } from './util/isExpired'; import { isSessionExpired } from './util/isSessionExpired'; -import { logInfo } from './util/log'; +import { logInfo, logInfoNextTick } from './util/log'; import { sendReplay } from './util/sendReplay'; import type { SKIPPED } from './util/throttle'; import { throttle, THROTTLED } from './util/throttle'; @@ -250,7 +250,10 @@ export class ReplayContainer implements ReplayContainerInterface { this.recordingMode = 'buffer'; } - logInfo(`[Replay] Starting replay in ${this.recordingMode} mode`, this._options._experiments.traceInternals); + logInfoNextTick( + `[Replay] Starting replay in ${this.recordingMode} mode`, + this._options._experiments.traceInternals, + ); this._initializeRecording(); } @@ -271,7 +274,7 @@ export class ReplayContainer implements ReplayContainerInterface { throw new Error('Replay buffering is in progress, call `flush()` to save the replay'); } - logInfo('[Replay] Starting replay in session mode', this._options._experiments.traceInternals); + logInfoNextTick('[Replay] Starting replay in session mode', this._options._experiments.traceInternals); const previousSessionId = this.session && this.session.id; @@ -300,7 +303,7 @@ export class ReplayContainer implements ReplayContainerInterface { throw new Error('Replay recording is already in progress'); } - logInfo('[Replay] Starting replay in buffer mode', this._options._experiments.traceInternals); + logInfoNextTick('[Replay] Starting replay in buffer mode', this._options._experiments.traceInternals); const previousSessionId = this.session && this.session.id; diff --git a/packages/replay/src/session/fetchSession.ts b/packages/replay/src/session/fetchSession.ts index 2d8f3f98a8aa..43e162b5f3d6 100644 --- a/packages/replay/src/session/fetchSession.ts +++ b/packages/replay/src/session/fetchSession.ts @@ -1,7 +1,7 @@ import { REPLAY_SESSION_KEY, WINDOW } from '../constants'; import type { Session } from '../types'; import { hasSessionStorage } from '../util/hasSessionStorage'; -import { logInfo } from '../util/log'; +import { logInfoNextTick } from '../util/log'; import { makeSession } from './Session'; /** @@ -22,7 +22,7 @@ export function fetchSession(traceInternals?: boolean): Session | null { const sessionObj = JSON.parse(sessionStringFromStorage) as Session; - logInfo('[Replay] Loading existing session', traceInternals); + logInfoNextTick('[Replay] Loading existing session', traceInternals); return makeSession(sessionObj); } catch { diff --git a/packages/replay/src/session/getSession.ts b/packages/replay/src/session/getSession.ts index b26921e58938..da3184f05296 100644 --- a/packages/replay/src/session/getSession.ts +++ b/packages/replay/src/session/getSession.ts @@ -1,6 +1,6 @@ import type { Session, SessionOptions, Timeouts } from '../types'; import { isSessionExpired } from '../util/isSessionExpired'; -import { logInfo } from '../util/log'; +import { logInfoNextTick } from '../util/log'; import { createSession } from './createSession'; import { fetchSession } from './fetchSession'; import { makeSession } from './Session'; @@ -44,10 +44,10 @@ export function getSession({ // and when this session is expired, it will not be renewed until user // reloads. const discardedSession = makeSession({ sampled: false }); - logInfo('[Replay] Session should not be refreshed', traceInternals); + logInfoNextTick('[Replay] Session should not be refreshed', traceInternals); return { type: 'new', session: discardedSession }; } else { - logInfo('[Replay] Session has expired', traceInternals); + logInfoNextTick('[Replay] Session has expired', traceInternals); } // Otherwise continue to create a new session } @@ -57,7 +57,7 @@ export function getSession({ sessionSampleRate, allowBuffering, }); - logInfo('[Replay] Created new session', traceInternals); + logInfoNextTick('[Replay] Created new session', traceInternals); return { type: 'new', session: newSession }; } diff --git a/packages/replay/src/util/log.ts b/packages/replay/src/util/log.ts index fbb107ad48f7..9aa650a81264 100644 --- a/packages/replay/src/util/log.ts +++ b/packages/replay/src/util/log.ts @@ -11,22 +11,42 @@ export function logInfo(message: string, shouldAddBreadcrumb?: boolean): void { logger.info(message); + if (shouldAddBreadcrumb) { + addBreadcrumb(message); + } +} + +/** + * Log a message, and add a breadcrumb in the next tick. + * This is necessary when the breadcrumb may be added before the replay is initialized. + */ +export function logInfoNextTick(message: string, shouldAddBreadcrumb?: boolean): void { + if (!__DEBUG_BUILD__) { + return; + } + + logger.info(message); + if (shouldAddBreadcrumb) { // Wait a tick here to avoid race conditions for some initial logs // which may be added before replay is initialized setTimeout(() => { - const hub = getCurrentHub(); - hub.addBreadcrumb( - { - category: 'console', - data: { - logger: 'replay', - }, - level: 'info', - message, - }, - { level: 'info' }, - ); + addBreadcrumb(message); }, 0); } } + +function addBreadcrumb(message: string): void { + const hub = getCurrentHub(); + hub.addBreadcrumb( + { + category: 'console', + data: { + logger: 'replay', + }, + level: 'info', + message, + }, + { level: 'info' }, + ); +} diff --git a/packages/replay/test/integration/flush.test.ts b/packages/replay/test/integration/flush.test.ts index 2ebd0dcc6923..611a1043df1a 100644 --- a/packages/replay/test/integration/flush.test.ts +++ b/packages/replay/test/integration/flush.test.ts @@ -329,6 +329,8 @@ describe('Integration | flush', () => { sessionStorage.clear(); clearSession(replay); replay['_loadAndCheckSession'](); + await new Promise(process.nextTick); + jest.setSystemTime(BASE_TIMESTAMP); // Clear the event buffer to simulate no checkout happened replay.eventBuffer!.clear(); @@ -343,41 +345,40 @@ describe('Integration | flush', () => { expect(mockFlush).toHaveBeenCalledTimes(1); expect(mockSendReplay).toHaveBeenCalledTimes(1); - expect(mockSendReplay).toHaveBeenLastCalledWith( - expect.objectContaining({ - recordingData: JSON.stringify([ - { - type: 5, - timestamp: BASE_TIMESTAMP, - data: { - tag: 'breadcrumb', - payload: { - timestamp: BASE_TIMESTAMP / 1000, - type: 'default', - category: 'ui.click', - message: '', - data: {}, - }, - }, + + 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: 'ui.click', + message: '', + data: {}, }, - { - type: 5, - timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, - data: { - tag: 'breadcrumb', - payload: { - timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY) / 1000, - type: 'default', - category: 'console', - data: { logger: 'replay' }, - level: 'info', - message: '[Replay] Flushing initial segment without checkout.', - }, - }, + }, + }, + { + type: 5, + timestamp: BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY, + data: { + tag: 'breadcrumb', + payload: { + timestamp: (BASE_TIMESTAMP + DEFAULT_FLUSH_MIN_DELAY) / 1000, + type: 'default', + category: 'console', + data: { logger: 'replay' }, + level: 'info', + message: '[Replay] Flushing initial segment without checkout.', }, - ]), - }), - ); + }, + }, + ]); replay.getOptions()._experiments.traceInternals = false; });