debug(replay): Add debugging statements around event buffer (#14014)

This is not intended to be merged to prod, I would like to debug how/why
we keep hitting EventBuffer limits on Sentry SaaS. Aside from debugging
statements, there should be no other behavioral changes.

---------

Co-authored-by: Catherine Lee <55311782+c298lee@users.noreply.github.com>

Author: billyvg

.size-limit.js

@@ -79,7 +79,7 @@ module.exports = [
     path: 'packages/browser/build/npm/esm/index.js',
     import: createImport('init', 'browserTracingIntegration', 'replayIntegration', 'replayCanvasIntegration'),
     gzip: true,
-    limit: '78 KB',
+    limit: '80 KB',
   },
   {
     name: '@sentry/browser (incl. Tracing, Replay, Feedback)',

packages/replay-internal/src/eventBuffer/EventBufferCompressionWorker.ts

@@ -67,6 +67,12 @@ export class EventBufferCompressionWorker implements EventBuffer {
     this._totalSize += data.length;
 
     if (this._totalSize > REPLAY_MAX_EVENT_BUFFER_SIZE) {
+      DEBUG_BUILD &&
+        logger.info(
+          `Cannot add new event with raw size of ${data.length} to existing buffer of size ${
+            this._totalSize - data.length
+          }`,
+        );
       return Promise.reject(new EventBufferSizeExceededError());
     }
 
@@ -82,14 +88,20 @@ export class EventBufferCompressionWorker implements EventBuffer {
 
   /** @inheritdoc */
   public clear(): void {
+    DEBUG_BUILD && logger.info(`Clearing event buffer (${this._totalSize})`);
     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
-    this._worker.postMessage('clear').then(null, e => {
-      DEBUG_BUILD && logger.exception(e, 'Sending "clear" message to worker failed', e);
-    });
+    this._worker.postMessage('clear').then(
+      () => {
+        DEBUG_BUILD && logger.info('Event buffer cleared within worker');
+      },
+      e => {
+        DEBUG_BUILD && logger.exception(e, 'Sending "clear" message to worker failed', e);
+      },
+    );
   }
 
   /** @inheritdoc */

packages/replay-internal/src/eventBuffer/EventBufferProxy.ts

@@ -115,6 +115,7 @@ export class EventBufferProxy implements EventBuffer {
     // Wait for original events to be re-added before resolving
     try {
       await Promise.all(addEventPromises);
+      DEBUG_BUILD && logger.info('Finished switching to compression worker');
 
       // Can now clear fallback buffer as it's no longer necessary
       this._fallback.clear();

packages/replay-internal/src/replay.ts

@@ -1,6 +1,13 @@
 /* eslint-disable max-lines */ // TODO: We might want to split this file up
 import { EventType, record } from '@sentry-internal/rrweb';
-import { SEMANTIC_ATTRIBUTE_SENTRY_SOURCE, getActiveSpan, getClient, getRootSpan, spanToJSON } from '@sentry/core';
+import {
+  SEMANTIC_ATTRIBUTE_SENTRY_SOURCE,
+  getActiveSpan,
+  getClient,
+  getRootSpan,
+  setTag,
+  spanToJSON,
+} from '@sentry/core';
 import type { ReplayRecordingMode, Span } from '@sentry/types';
 import { logger } from './util/logger';
 
@@ -1215,28 +1222,14 @@ export class ReplayContainer implements ReplayContainerInterface {
       return;
     }
 
-    const start = this.session.started;
-    const now = Date.now();
-    const duration = now - start;
-
     // A flush is about to happen, cancel any queued flushes
     this._debouncedFlush.cancel();
 
-    // If session is too short, or too long (allow some wiggle room over maxReplayDuration), do not send it
-    // This _should_ not happen, but it may happen if flush is triggered due to a page activity change or similar
-    const tooShort = duration < this._options.minReplayDuration;
-    const tooLong = duration > this._options.maxReplayDuration + 5_000;
-    if (tooShort || tooLong) {
-      DEBUG_BUILD &&
-        logger.info(
-          `Session duration (${Math.floor(duration / 1000)}s) is too ${
-            tooShort ? 'short' : 'long'
-          }, not sending replay.`,
-        );
+    const isValidDuration = this._checkReplayDurationDuringFlush();
 
-      if (tooShort) {
-        this._debouncedFlush();
-      }
+    // XXX: disregard durations for buffer mode for debug purposes
+    if (!isValidDuration && this.recordingMode !== 'buffer') {
+      DEBUG_BUILD && logger.info('Invalid duration while buffering');
       return;
     }
 
@@ -1272,6 +1265,47 @@ export class ReplayContainer implements ReplayContainerInterface {
     }
   };
 
+  /**
+   * Checks to see if replay duration is within bounds during a flush. If it is
+   * too short, will queue up a new flush to prevent short replays.
+   *
+   * Returns true if duration is ok, false otherwise
+   */
+  private _checkReplayDurationDuringFlush(): boolean {
+    if (!this.session) {
+      return false;
+    }
+
+    const start = this.session.started;
+    const now = Date.now();
+    const duration = now - start;
+
+    // If session is too short, or too long (allow some wiggle room over maxReplayDuration), do not send it
+    // This _should_ not happen, but it may happen if flush is triggered due to a page activity change or similar
+    const tooShort = duration < this._options.minReplayDuration;
+    const tooLong = duration > this._options.maxReplayDuration + 5_000;
+    if (tooShort || tooLong) {
+      DEBUG_BUILD &&
+        logger.info(
+          `Session duration (${Math.floor(duration / 1000)}s) is too ${
+            tooShort ? 'short' : 'long'
+          }, not sending replay.`,
+        );
+
+      if (tooShort) {
+        this._debouncedFlush();
+      }
+
+      // XXX: disregard durations for buffer mode for debug purposes
+      if (this.recordingMode === 'buffer') {
+        setTag(`replay.${tooShort ? 'tooShort' : 'tooLong'}`, true);
+      }
+      return false;
+    }
+
+    return true;
+  }
+
   /** Save the session, if it is sticky */
   private _maybeSaveSession(): void {
     if (this.session && this._options.stickySession) {

packages/replay-internal/src/util/handleRecordingEmit.ts

@@ -43,6 +43,7 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
       // dependent on this reset.
       if (replay.recordingMode === 'buffer' && isCheckout) {
         replay.setInitialState();
+        DEBUG_BUILD && logger.info(`Adding checkout event while in buffer mode (${JSON.stringify(event).length})`);
       }
 
       // If the event is not added (e.g. due to being paused, disabled, or out of the max replay duration),
@@ -74,7 +75,11 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
       // When in buffer mode, make sure we adjust the session started date to the current earliest event of the buffer
       // this should usually be the timestamp of the checkout event, but to be safe...
       if (replay.recordingMode === 'buffer' && session && replay.eventBuffer) {
+        DEBUG_BUILD &&
+          logger.info('Attempting to fetch earliest event from event buffer type: ', replay.eventBuffer.type);
+
         const earliestEvent = replay.eventBuffer.getEarliestTimestamp();
+
         if (earliestEvent) {
           DEBUG_BUILD &&
             logger.info(`Updating session start time to earliest event in buffer to ${new Date(earliestEvent)}`);
@@ -84,6 +89,9 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
           if (replay.getOptions().stickySession) {
             saveSession(session);
           }
+        } else {
+          // XXX(billy): debugging
+          DEBUG_BUILD && logger.warn('Unable to find earliest event in event buffer');
         }
       }