ref(replay): Log warning if trying to flush initial segment without checkout (#8748)

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.

Author: mydea

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 */

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');
   }

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();

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;
 
@@ -1151,6 +1154,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) {

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 {

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 };
 }

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.
    */

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();

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' },
+  );
+}

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,71 @@ 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']();
+    await new Promise(process.nextTick);
+    jest.setSystemTime(BASE_TIMESTAMP);
+
+    // 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);
+
+    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: '<unknown>',
+            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;
   });
 });