From 60c10818293e7149498ba087000258f63c23d212 Mon Sep 17 00:00:00 2001
From: Francesco Novy <francesco.novy@sentry.io>
Date: Thu, 3 Aug 2023 08:47:28 +0200
Subject: [PATCH] ref(replay): Improve status logging (#8709)

This streamlines & improves logging for replay status, adding more logs
for certain things to be better able to see what's going on, and
adapting the `traceInternals` setting to result in console breadcrumbs
being added (which should show up both in replay and for e.g. sentry
errors etc).

While at it I also fixed some `any` eslint warnings in replay.

ref: https://github.com/getsentry/sentry-javascript/issues/8400
---
 packages/replay/jest.setup.ts                 | 25 +++++----
 .../src/eventBuffer/EventBufferProxy.ts       |  3 +-
 .../replay/src/eventBuffer/WorkerHandler.ts   |  3 +-
 packages/replay/src/eventBuffer/index.ts      |  8 +--
 packages/replay/src/replay.ts                 | 54 +++++++++++--------
 packages/replay/src/session/createSession.ts  |  4 --
 packages/replay/src/session/fetchSession.ts   |  5 +-
 packages/replay/src/session/getSession.ts     | 12 +++--
 packages/replay/src/types/replayFrame.ts      |  8 +--
 .../replay/src/util/handleRecordingEmit.ts    |  9 ++--
 packages/replay/src/util/log.ts               | 28 ++++++++++
 packages/replay/src/util/sendReplayRequest.ts |  4 +-
 12 files changed, 106 insertions(+), 57 deletions(-)
 create mode 100644 packages/replay/src/util/log.ts

diff --git a/packages/replay/jest.setup.ts b/packages/replay/jest.setup.ts
index 665d29e2386a..093c97dcdce4 100644
--- a/packages/replay/jest.setup.ts
+++ b/packages/replay/jest.setup.ts
@@ -129,21 +129,24 @@ function checkCallForSentReplay(
 }
 
 /**
-* Only want calls that send replay events, i.e. ignore error events
-*/
+ * Only want calls that send replay events, i.e. ignore error events
+ */
+// eslint-disable-next-line @typescript-eslint/no-explicit-any
 function getReplayCalls(calls: any[][][]): any[][][] {
-  return calls.map(call => {
-    const arg = call[0];
+  return calls
+    .map(call => {
+      const arg = call[0];
       if (arg.length !== 2) {
         return [];
       }
 
-      if (!arg[1][0].find(({type}: {type: string}) => ['replay_event', 'replay_recording'].includes(type))) {
+      if (!arg[1][0].find(({ type }: { type: string }) => ['replay_event', 'replay_recording'].includes(type))) {
         return [];
       }
 
-      return [ arg ];
-  }).filter(Boolean);
+      return [arg];
+    })
+    .filter(Boolean);
 }
 
 /**
@@ -159,9 +162,11 @@ const toHaveSentReplay = function (
 
   let result: CheckCallForSentReplayResult;
 
-  const expectedKeysLength = expected ? ('sample' in expected ? Object.keys(expected.sample) : Object.keys(expected)).length : 0;
+  const expectedKeysLength = expected
+    ? ('sample' in expected ? Object.keys(expected.sample) : Object.keys(expected)).length
+    : 0;
 
-  const replayCalls = getReplayCalls(calls)
+  const replayCalls = getReplayCalls(calls);
 
   for (const currentCall of replayCalls) {
     result = checkCallForSentReplay.call(this, currentCall[0], expected);
@@ -213,7 +218,7 @@ const toHaveLastSentReplay = function (
   expected?: SentReplayExpected | { sample: SentReplayExpected; inverse: boolean },
 ) {
   const { calls } = (getCurrentHub().getClient()?.getTransport()?.send as MockTransport).mock;
-  const replayCalls = getReplayCalls(calls)
+  const replayCalls = getReplayCalls(calls);
 
   const lastCall = replayCalls[calls.length - 1]?.[0];
 
diff --git a/packages/replay/src/eventBuffer/EventBufferProxy.ts b/packages/replay/src/eventBuffer/EventBufferProxy.ts
index df50634bf3eb..2b3c2329f876 100644
--- a/packages/replay/src/eventBuffer/EventBufferProxy.ts
+++ b/packages/replay/src/eventBuffer/EventBufferProxy.ts
@@ -2,6 +2,7 @@ import type { ReplayRecordingData } from '@sentry/types';
 import { logger } from '@sentry/utils';
 
 import type { AddEventResult, EventBuffer, EventBufferType, RecordingEvent } from '../types';
+import { logInfo } from '../util/log';
 import { EventBufferArray } from './EventBufferArray';
 import { EventBufferCompressionWorker } from './EventBufferCompressionWorker';
 
@@ -79,7 +80,7 @@ export class EventBufferProxy implements EventBuffer {
     } catch (error) {
       // If the worker fails to load, we fall back to the simple buffer.
       // Nothing more to do from our side here
-      __DEBUG_BUILD__ && logger.log('[Replay] Failed to load the compression worker, falling back to simple buffer');
+      logInfo('[Replay] Failed to load the compression worker, falling back to simple buffer');
       return;
     }
 
diff --git a/packages/replay/src/eventBuffer/WorkerHandler.ts b/packages/replay/src/eventBuffer/WorkerHandler.ts
index 711b21bd3380..f9a84c6bdbf1 100644
--- a/packages/replay/src/eventBuffer/WorkerHandler.ts
+++ b/packages/replay/src/eventBuffer/WorkerHandler.ts
@@ -1,6 +1,7 @@
 import { logger } from '@sentry/utils';
 
 import type { WorkerRequest, WorkerResponse } from '../types';
+import { logInfo } from '../util/log';
 
 /**
  * Event buffer that uses a web worker to compress events.
@@ -55,7 +56,7 @@ export class WorkerHandler {
    * Destroy the worker.
    */
   public destroy(): void {
-    __DEBUG_BUILD__ && logger.log('[Replay] Destroying compression worker');
+    logInfo('[Replay] Destroying compression worker');
     this._worker.terminate();
   }
 
diff --git a/packages/replay/src/eventBuffer/index.ts b/packages/replay/src/eventBuffer/index.ts
index f0eb83c68243..07af24ae22a2 100644
--- a/packages/replay/src/eventBuffer/index.ts
+++ b/packages/replay/src/eventBuffer/index.ts
@@ -1,7 +1,7 @@
 import { getWorkerURL } from '@sentry-internal/replay-worker';
-import { logger } from '@sentry/utils';
 
 import type { EventBuffer } from '../types';
+import { logInfo } from '../util/log';
 import { EventBufferArray } from './EventBufferArray';
 import { EventBufferProxy } from './EventBufferProxy';
 
@@ -18,15 +18,15 @@ export function createEventBuffer({ useCompression }: CreateEventBufferParams):
     try {
       const workerUrl = getWorkerURL();
 
-      __DEBUG_BUILD__ && logger.log('[Replay] Using compression worker');
+      logInfo('[Replay] Using compression worker');
       const worker = new Worker(workerUrl);
       return new EventBufferProxy(worker);
     } catch (error) {
-      __DEBUG_BUILD__ && logger.log('[Replay] Failed to create compression worker');
+      logInfo('[Replay] Failed to create compression worker');
       // Fall back to use simple event buffer array
     }
   }
 
-  __DEBUG_BUILD__ && logger.log('[Replay] Using simple buffer');
+  logInfo('[Replay] Using simple buffer');
   return new EventBufferArray();
 }
diff --git a/packages/replay/src/replay.ts b/packages/replay/src/replay.ts
index a46554266653..d65be467d5f3 100644
--- a/packages/replay/src/replay.ts
+++ b/packages/replay/src/replay.ts
@@ -47,6 +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 { sendReplay } from './util/sendReplay';
 import type { SKIPPED } from './util/throttle';
 import { throttle, THROTTLED } from './util/throttle';
@@ -249,6 +250,8 @@ export class ReplayContainer implements ReplayContainerInterface {
       this.recordingMode = 'buffer';
     }
 
+    logInfo(`[Replay] Starting replay in ${this.recordingMode} mode`, this._options._experiments.traceInternals);
+
     this._initializeRecording();
   }
 
@@ -268,6 +271,8 @@ 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);
+
     const previousSessionId = this.session && this.session.id;
 
     const { session } = getSession({
@@ -277,6 +282,7 @@ export class ReplayContainer implements ReplayContainerInterface {
       // This is intentional: create a new session-based replay when calling `start()`
       sessionSampleRate: 1,
       allowBuffering: false,
+      traceInternals: this._options._experiments.traceInternals,
     });
 
     session.previousSessionId = previousSessionId;
@@ -294,6 +300,8 @@ 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);
+
     const previousSessionId = this.session && this.session.id;
 
     const { session } = getSession({
@@ -302,6 +310,7 @@ export class ReplayContainer implements ReplayContainerInterface {
       currentSession: this.session,
       sessionSampleRate: 0,
       allowBuffering: true,
+      traceInternals: this._options._experiments.traceInternals,
     });
 
     session.previousSessionId = previousSessionId;
@@ -362,15 +371,10 @@ export class ReplayContainer implements ReplayContainerInterface {
     }
 
     try {
-      if (__DEBUG_BUILD__) {
-        const msg = `[Replay] Stopping Replay${reason ? ` triggered by ${reason}` : ''}`;
-
-        // When `traceInternals` is enabled, we want to log this to the console
-        // Else, use the regular debug output
-        // eslint-disable-next-line
-        const log = this.getOptions()._experiments.traceInternals ? console.warn : logger.log;
-        log(msg);
-      }
+      logInfo(
+        `[Replay] Stopping Replay${reason ? ` triggered by ${reason}` : ''}`,
+        this._options._experiments.traceInternals,
+      );
 
       // We can't move `_isEnabled` after awaiting a flush, otherwise we can
       // enter into an infinite loop when `stop()` is called while flushing.
@@ -403,8 +407,14 @@ export class ReplayContainer implements ReplayContainerInterface {
    * not as thorough of a shutdown as `stop()`.
    */
   public pause(): void {
+    if (this._isPaused) {
+      return;
+    }
+
     this._isPaused = true;
     this.stopRecording();
+
+    logInfo('[Replay] Pausing replay', this._options._experiments.traceInternals);
   }
 
   /**
@@ -414,12 +424,14 @@ export class ReplayContainer implements ReplayContainerInterface {
    * new DOM checkout.`
    */
   public resume(): void {
-    if (!this._loadAndCheckSession()) {
+    if (!this._isPaused || !this._loadAndCheckSession()) {
       return;
     }
 
     this._isPaused = false;
     this.startRecording();
+
+    logInfo('[Replay] Resuming replay', this._options._experiments.traceInternals);
   }
 
   /**
@@ -436,9 +448,7 @@ export class ReplayContainer implements ReplayContainerInterface {
 
     const activityTime = Date.now();
 
-    // eslint-disable-next-line no-console
-    const log = this.getOptions()._experiments.traceInternals ? console.info : logger.info;
-    __DEBUG_BUILD__ && log(`[Replay] Converting buffer to session, starting at ${activityTime}`);
+    logInfo('[Replay] Converting buffer to session', this._options._experiments.traceInternals);
 
     // Allow flush to complete before resuming as a session recording, otherwise
     // the checkout from `startRecording` may be included in the payload.
@@ -746,6 +756,7 @@ export class ReplayContainer implements ReplayContainerInterface {
       currentSession: this.session,
       sessionSampleRate: this._options.sessionSampleRate,
       allowBuffering: this._options.errorSampleRate > 0 || this.recordingMode === 'buffer',
+      traceInternals: this._options._experiments.traceInternals,
     });
 
     // If session was newly created (i.e. was not loaded from storage), then
@@ -762,7 +773,7 @@ export class ReplayContainer implements ReplayContainerInterface {
     this.session = session;
 
     if (!this.session.sampled) {
-      void this.stop('session unsampled');
+      void this.stop('session not refreshed');
       return false;
     }
 
@@ -904,7 +915,7 @@ export class ReplayContainer implements ReplayContainerInterface {
       // If the user has come back to the page within SESSION_IDLE_PAUSE_DURATION
       // ms, we will re-use the existing session, otherwise create a new
       // session
-      __DEBUG_BUILD__ && logger.log('[Replay] Document has become active, but session has expired');
+      logInfo('[Replay] Document has become active, but session has expired');
       return;
     }
 
@@ -919,7 +930,7 @@ export class ReplayContainer implements ReplayContainerInterface {
    */
   private _triggerFullSnapshot(checkout = true): void {
     try {
-      __DEBUG_BUILD__ && logger.log('[Replay] Taking full rrweb snapshot');
+      logInfo('[Replay] Taking full rrweb snapshot');
       record.takeFullSnapshot(checkout);
     } catch (err) {
       this._handleException(err);
@@ -1121,13 +1132,10 @@ export class ReplayContainer implements ReplayContainerInterface {
     // If session is too short, or too long (allow some wiggle room over maxSessionLife), do not send it
     // This _should_ not happen, but it may happen if flush is triggered due to a page activity change or similar
     if (duration < this._options.minReplayDuration || duration > this.timeouts.maxSessionLife + 5_000) {
-      // eslint-disable-next-line no-console
-      const log = this.getOptions()._experiments.traceInternals ? console.warn : logger.warn;
-      __DEBUG_BUILD__ &&
-        log(
-          `[Replay] Session duration (${Math.floor(duration / 1000)}s) is too short or too long, not sending replay.`,
-        );
-
+      logInfo(
+        `[Replay] Session duration (${Math.floor(duration / 1000)}s) is too short or too long, not sending replay.`,
+        this._options._experiments.traceInternals,
+      );
       return;
     }
 
diff --git a/packages/replay/src/session/createSession.ts b/packages/replay/src/session/createSession.ts
index f5f2d120b92b..0ecd940a4dae 100644
--- a/packages/replay/src/session/createSession.ts
+++ b/packages/replay/src/session/createSession.ts
@@ -1,5 +1,3 @@
-import { logger } from '@sentry/utils';
-
 import type { Sampled, Session, SessionOptions } from '../types';
 import { isSampled } from '../util/isSampled';
 import { saveSession } from './saveSession';
@@ -23,8 +21,6 @@ export function createSession({ sessionSampleRate, allowBuffering, stickySession
     sampled,
   });
 
-  __DEBUG_BUILD__ && logger.log(`[Replay] Creating new session: ${session.id}`);
-
   if (stickySession) {
     saveSession(session);
   }
diff --git a/packages/replay/src/session/fetchSession.ts b/packages/replay/src/session/fetchSession.ts
index 3e89a9cbd049..2d8f3f98a8aa 100644
--- a/packages/replay/src/session/fetchSession.ts
+++ b/packages/replay/src/session/fetchSession.ts
@@ -1,12 +1,13 @@
 import { REPLAY_SESSION_KEY, WINDOW } from '../constants';
 import type { Session } from '../types';
 import { hasSessionStorage } from '../util/hasSessionStorage';
+import { logInfo } from '../util/log';
 import { makeSession } from './Session';
 
 /**
  * Fetches a session from storage
  */
-export function fetchSession(): Session | null {
+export function fetchSession(traceInternals?: boolean): Session | null {
   if (!hasSessionStorage()) {
     return null;
   }
@@ -21,6 +22,8 @@ export function fetchSession(): Session | null {
 
     const sessionObj = JSON.parse(sessionStringFromStorage) as Session;
 
+    logInfo('[Replay] Loading existing session', traceInternals);
+
     return makeSession(sessionObj);
   } catch {
     return null;
diff --git a/packages/replay/src/session/getSession.ts b/packages/replay/src/session/getSession.ts
index 73554a8860de..b26921e58938 100644
--- a/packages/replay/src/session/getSession.ts
+++ b/packages/replay/src/session/getSession.ts
@@ -1,7 +1,6 @@
-import { logger } from '@sentry/utils';
-
 import type { Session, SessionOptions, Timeouts } from '../types';
 import { isSessionExpired } from '../util/isSessionExpired';
+import { logInfo } from '../util/log';
 import { createSession } from './createSession';
 import { fetchSession } from './fetchSession';
 import { makeSession } from './Session';
@@ -13,6 +12,8 @@ interface GetSessionParams extends SessionOptions {
    * The current session (e.g. if stickySession is off)
    */
   currentSession?: Session;
+
+  traceInternals?: boolean;
 }
 
 /**
@@ -24,9 +25,10 @@ export function getSession({
   stickySession,
   sessionSampleRate,
   allowBuffering,
+  traceInternals,
 }: GetSessionParams): { type: 'new' | 'saved'; session: Session } {
   // If session exists and is passed, use it instead of always hitting session storage
-  const session = currentSession || (stickySession && fetchSession());
+  const session = currentSession || (stickySession && fetchSession(traceInternals));
 
   if (session) {
     // If there is a session, check if it is valid (e.g. "last activity" time
@@ -42,9 +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);
       return { type: 'new', session: discardedSession };
     } else {
-      __DEBUG_BUILD__ && logger.log('[Replay] Session has expired');
+      logInfo('[Replay] Session has expired', traceInternals);
     }
     // Otherwise continue to create a new session
   }
@@ -54,6 +57,7 @@ export function getSession({
     sessionSampleRate,
     allowBuffering,
   });
+  logInfo('[Replay] Created new session', traceInternals);
 
   return { type: 'new', session: newSession };
 }
diff --git a/packages/replay/src/types/replayFrame.ts b/packages/replay/src/types/replayFrame.ts
index f3fb594829d3..5eca0be68466 100644
--- a/packages/replay/src/types/replayFrame.ts
+++ b/packages/replay/src/types/replayFrame.ts
@@ -11,6 +11,8 @@ import type {
 } from './performance';
 import type { EventType } from './rrweb';
 
+type AnyRecord = Record<string, any>; // eslint-disable-line @typescript-eslint/no-explicit-any
+
 interface BaseBreadcrumbFrame {
   timestamp: number;
   /**
@@ -18,7 +20,7 @@ interface BaseBreadcrumbFrame {
    */
   type: string;
   category: string;
-  data?: Record<string, any>;
+  data?: AnyRecord;
   message?: string;
 }
 
@@ -28,7 +30,7 @@ interface BaseDomFrameData {
     id: number;
     tagName: string;
     textContent: string;
-    attributes: Record<string, any>;
+    attributes: AnyRecord;
   };
 }
 
@@ -141,7 +143,7 @@ interface BaseSpanFrame {
   description: string;
   startTimestamp: number;
   endTimestamp: number;
-  data?: undefined | Record<string, any>;
+  data?: undefined | AnyRecord;
 }
 
 interface HistoryFrame extends BaseSpanFrame {
diff --git a/packages/replay/src/util/handleRecordingEmit.ts b/packages/replay/src/util/handleRecordingEmit.ts
index 4039fad5caa8..9e22e57f6255 100644
--- a/packages/replay/src/util/handleRecordingEmit.ts
+++ b/packages/replay/src/util/handleRecordingEmit.ts
@@ -4,6 +4,7 @@ import { logger } from '@sentry/utils';
 import { saveSession } from '../session/saveSession';
 import type { AddEventResult, OptionFrameEvent, RecordingEvent, ReplayContainer } from '../types';
 import { addEvent } from './addEvent';
+import { logInfo } from './log';
 
 type RecordingEmitCallback = (event: RecordingEvent, isCheckout?: boolean) => void;
 
@@ -72,10 +73,10 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
       if (replay.recordingMode === 'buffer' && replay.session && replay.eventBuffer) {
         const earliestEvent = replay.eventBuffer.getEarliestTimestamp();
         if (earliestEvent) {
-          // eslint-disable-next-line no-console
-          const log = replay.getOptions()._experiments.traceInternals ? console.info : logger.info;
-          __DEBUG_BUILD__ &&
-            log(`[Replay] Updating session start time to earliest event in buffer at ${earliestEvent}`);
+          logInfo(
+            `[Replay] Updating session start time to earliest event in buffer to ${new Date(earliestEvent)}`,
+            replay.getOptions()._experiments.traceInternals,
+          );
 
           replay.session.started = earliestEvent;
 
diff --git a/packages/replay/src/util/log.ts b/packages/replay/src/util/log.ts
new file mode 100644
index 000000000000..b5aca4039429
--- /dev/null
+++ b/packages/replay/src/util/log.ts
@@ -0,0 +1,28 @@
+import { getCurrentHub } from '@sentry/core';
+import { logger } from '@sentry/utils';
+
+/**
+ * Log a message in debug mode, and add a breadcrumb when _experiment.traceInternals is enabled.
+ */
+export function logInfo(message: string, shouldAddBreadcrumb?: boolean): void {
+  if (!__DEBUG_BUILD__) {
+    return;
+  }
+
+  logger.info(message);
+
+  if (shouldAddBreadcrumb) {
+    const hub = getCurrentHub();
+    hub.addBreadcrumb(
+      {
+        category: 'console',
+        data: {
+          logger: 'replay',
+        },
+        level: 'info',
+        message,
+      },
+      { level: 'info' },
+    );
+  }
+}
diff --git a/packages/replay/src/util/sendReplayRequest.ts b/packages/replay/src/util/sendReplayRequest.ts
index f0a01f0bf79a..1bce7f4fd132 100644
--- a/packages/replay/src/util/sendReplayRequest.ts
+++ b/packages/replay/src/util/sendReplayRequest.ts
@@ -1,10 +1,10 @@
 import { getCurrentHub } from '@sentry/core';
 import type { ReplayEvent, TransportMakeRequestResponse } from '@sentry/types';
-import { logger } from '@sentry/utils';
 
 import { REPLAY_EVENT_NAME, UNABLE_TO_SEND_REPLAY } from '../constants';
 import type { SendReplayData } from '../types';
 import { createReplayEnvelope } from './createReplayEnvelope';
+import { logInfo } from './log';
 import { prepareRecordingData } from './prepareRecordingData';
 import { prepareReplayEvent } from './prepareReplayEvent';
 
@@ -55,7 +55,7 @@ export async function sendReplayRequest({
   if (!replayEvent) {
     // Taken from baseclient's `_processEvent` method, where this is handled for errors/transactions
     client.recordDroppedEvent('event_processor', 'replay', baseEvent);
-    __DEBUG_BUILD__ && logger.log('An event processor returned `null`, will not send event.');
+    logInfo('An event processor returned `null`, will not send event.');
     return;
   }