Skip to content

fix(replay): Ensure handleRecordingEmit aborts when event is not added #8938

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 11, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 3 additions & 2 deletions packages/replay/src/replay.ts
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,7 @@ import type {
Timeouts,
} from './types';
import { ReplayEventTypeCustom } from './types';
import { addEvent } from './util/addEvent';
import { addEvent, addEventSync } from './util/addEvent';
import { addGlobalListeners } from './util/addGlobalListeners';
import { addMemoryEntry } from './util/addMemoryEntry';
import { createBreadcrumb } from './util/createBreadcrumb';
Expand Down Expand Up @@ -666,7 +666,8 @@ export class ReplayContainer implements ReplayContainerInterface {
});

this.addUpdate(() => {
void addEvent(this, {
// Return `false` if the event _was_ added, as that means we schedule a flush
return !addEventSync(this, {
type: ReplayEventTypeCustom,
timestamp: breadcrumb.timestamp || 0,
data: {
Expand Down
83 changes: 59 additions & 24 deletions packages/replay/src/util/addEvent.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,39 +13,46 @@ function isCustomEvent(event: RecordingEvent): event is ReplayFrameEvent {

/**
* Add an event to the event buffer.
* In contrast to `addEvent`, this does not return a promise & does not wait for the adding of the event to succeed/fail.
* Instead this returns `true` if we tried to add the event, else false.
* It returns `false` e.g. if we are paused, disabled, or out of the max replay duration.
*
* `isCheckout` is true if this is either the very first event, or an event triggered by `checkoutEveryNms`.
*/
export async function addEvent(
export function addEventSync(replay: ReplayContainer, event: RecordingEvent, isCheckout?: boolean): boolean {
if (!shouldAddEvent(replay, event)) {
return false;
}

void _addEvent(replay, event, isCheckout);

return true;
}

/**
* Add an event to the event buffer.
* Resolves to `null` if no event was added, else to `void`.
*
* `isCheckout` is true if this is either the very first event, or an event triggered by `checkoutEveryNms`.
*/
export function addEvent(
replay: ReplayContainer,
event: RecordingEvent,
isCheckout?: boolean,
): Promise<AddEventResult | null> {
if (!replay.eventBuffer) {
// This implies that `_isEnabled` is false
return null;
}

if (replay.isPaused()) {
// Do not add to event buffer when recording is paused
return null;
if (!shouldAddEvent(replay, event)) {
return Promise.resolve(null);
}

const timestampInMs = timestampToMs(event.timestamp);

// Throw out events that happen more than 5 minutes ago. This can happen if
// page has been left open and idle for a long period of time and user
// comes back to trigger a new session. The performance entries rely on
// `performance.timeOrigin`, which is when the page first opened.
if (timestampInMs + replay.timeouts.sessionIdlePause < Date.now()) {
return null;
}
return _addEvent(replay, event, isCheckout);
}

// Throw out events that are +60min from the initial timestamp
if (timestampInMs > replay.getContext().initialTimestamp + replay.getOptions().maxReplayDuration) {
logInfo(
`[Replay] Skipping event with timestamp ${timestampInMs} because it is after maxReplayDuration`,
replay.getOptions()._experiments.traceInternals,
);
async function _addEvent(
replay: ReplayContainer,
event: RecordingEvent,
isCheckout?: boolean,
): Promise<AddEventResult | null> {
if (!replay.eventBuffer) {
return null;
}

Expand Down Expand Up @@ -81,6 +88,34 @@ export async function addEvent(
}
}

/** Exported only for tests. */
export function shouldAddEvent(replay: ReplayContainer, event: RecordingEvent): boolean {
if (!replay.eventBuffer || replay.isPaused() || !replay.isEnabled()) {
return false;
}

const timestampInMs = timestampToMs(event.timestamp);

// Throw out events that happen more than 5 minutes ago. This can happen if
// page has been left open and idle for a long period of time and user
// comes back to trigger a new session. The performance entries rely on
// `performance.timeOrigin`, which is when the page first opened.
if (timestampInMs + replay.timeouts.sessionIdlePause < Date.now()) {
return false;
}

// Throw out events that are +60min from the initial timestamp
if (timestampInMs > replay.getContext().initialTimestamp + replay.getOptions().maxReplayDuration) {
logInfo(
`[Replay] Skipping event with timestamp ${timestampInMs} because it is after maxReplayDuration`,
replay.getOptions()._experiments.traceInternals,
);
return false;
}

return true;
}

function maybeApplyCallback(
event: RecordingEvent,
callback: ReplayPluginOptions['beforeAddRecordingEvent'],
Expand Down
21 changes: 12 additions & 9 deletions packages/replay/src/util/handleRecordingEmit.ts
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,8 @@ import { EventType } from '@sentry-internal/rrweb';
import { logger } from '@sentry/utils';

import { saveSession } from '../session/saveSession';
import type { AddEventResult, RecordingEvent, ReplayContainer, ReplayOptionFrameEvent } from '../types';
import { addEvent } from './addEvent';
import type { RecordingEvent, ReplayContainer, ReplayOptionFrameEvent } from '../types';
import { addEventSync } from './addEvent';
import { logInfo } from './log';

type RecordingEmitCallback = (event: RecordingEvent, isCheckout?: boolean) => void;
Expand Down Expand Up @@ -40,9 +40,12 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
replay.setInitialState();
}

// We need to clear existing events on a checkout, otherwise they are
// incremental event updates and should be appended
void addEvent(replay, event, isCheckout);
// If the event is not added (e.g. due to being paused, disabled, or out of the max replay duration),
// Skip all further steps
if (!addEventSync(replay, event, isCheckout)) {
// Return true to skip scheduling a debounced flush
return true;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This API for addUpdate is always confusing for me, I always have to double check what I should return to do what 😅 Nothing to do but maybe we can find a clearer API for this at some point.

}

// Different behavior for full snapshots (type=2), ignore other event types
// See https://github.com/rrweb-io/rrweb/blob/d8f9290ca496712aa1e7d472549480c4e7876594/packages/rrweb/src/types.ts#L16
Expand All @@ -56,7 +59,7 @@ export function getHandleRecordingEmit(replay: ReplayContainer): RecordingEmitCa
//
// `isCheckout` is always true, but want to be explicit that it should
// only be added for checkouts
void addSettingsEvent(replay, isCheckout);
addSettingsEvent(replay, isCheckout);

// If there is a previousSessionId after a full snapshot occurs, then
// the replay session was started due to session expiration. The new session
Expand Down Expand Up @@ -130,11 +133,11 @@ export function createOptionsEvent(replay: ReplayContainer): ReplayOptionFrameEv
* Add a "meta" event that contains a simplified view on current configuration
* options. This should only be included on the first segment of a recording.
*/
function addSettingsEvent(replay: ReplayContainer, isCheckout?: boolean): Promise<AddEventResult | null> {
function addSettingsEvent(replay: ReplayContainer, isCheckout?: boolean): void {
// Only need to add this event when sending the first segment
if (!isCheckout || !replay.session || replay.session.segmentId !== 0) {
return Promise.resolve(null);
return;
}

return addEvent(replay, createOptionsEvent(replay), false);
addEventSync(replay, createOptionsEvent(replay), false);
}
70 changes: 0 additions & 70 deletions packages/replay/test/integration/errorSampleRate.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -810,76 +810,6 @@ describe('Integration | errorSampleRate', () => {
expect(replay).toHaveLastSentReplay();
});

it('does not refresh replay based on earliest event in buffer', async () => {
jest.setSystemTime(BASE_TIMESTAMP);

const TEST_EVENT = getTestEventIncremental({ timestamp: BASE_TIMESTAMP - 60000 });
mockRecord._emitter(TEST_EVENT);

expect(mockRecord.takeFullSnapshot).not.toHaveBeenCalled();
expect(replay).not.toHaveLastSentReplay();

jest.runAllTimers();
await new Promise(process.nextTick);

expect(replay).not.toHaveLastSentReplay();
captureException(new Error('testing'));

await waitForBufferFlush();

expect(replay).toHaveLastSentReplay();

// Flush from calling `stopRecording`
await waitForFlush();

// Now wait after session expires - should stop recording
mockRecord.takeFullSnapshot.mockClear();
(getCurrentHub().getClient()!.getTransport()!.send as unknown as jest.SpyInstance<any>).mockClear();

expect(replay).not.toHaveLastSentReplay();

const TICKS = 80;

// We advance time so that we are on the border of expiring, taking into
// account that TEST_EVENT timestamp is 60000 ms before BASE_TIMESTAMP. The
// 3 DEFAULT_FLUSH_MIN_DELAY is to account for the `waitForFlush` that has
// happened, and for the next two that will happen. The first following
// `waitForFlush` does not expire session, but the following one will.
jest.advanceTimersByTime(SESSION_IDLE_EXPIRE_DURATION - 60000 - 3 * DEFAULT_FLUSH_MIN_DELAY - TICKS);
await new Promise(process.nextTick);

mockRecord._emitter(TEST_EVENT);
expect(replay).not.toHaveLastSentReplay();
await waitForFlush();

expect(replay).not.toHaveLastSentReplay();
expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0);
expect(replay.isEnabled()).toBe(true);

mockRecord._emitter(TEST_EVENT);
expect(replay).not.toHaveLastSentReplay();
await waitForFlush();

expect(replay).not.toHaveLastSentReplay();
expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0);
expect(replay.isEnabled()).toBe(true);

const sessionId = replay.getSessionId();

// It's hard to test, but if we advance the below time less 1 ms, it should
// be enabled, but we can't trigger a session check via flush without
// incurring another DEFAULT_FLUSH_MIN_DELAY timeout.
jest.advanceTimersByTime(60000 - DEFAULT_FLUSH_MIN_DELAY);
mockRecord._emitter(TEST_EVENT);
expect(replay).not.toHaveLastSentReplay();
await waitForFlush();

expect(replay).not.toHaveLastSentReplay();
expect(mockRecord.takeFullSnapshot).toHaveBeenCalledTimes(0);
expect(replay.isEnabled()).toBe(true);
expect(replay.getSessionId()).not.toBe(sessionId);
});

it('handles very long active buffer session', async () => {
const stepDuration = 10_000;
const steps = 5_000;
Expand Down
34 changes: 11 additions & 23 deletions packages/replay/test/integration/flush.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -403,6 +403,8 @@ describe('Integration | flush', () => {
it('logs warning if adding event that is after maxReplayDuration', async () => {
replay.getOptions()._experiments.traceInternals = true;

const spyLogger = jest.spyOn(SentryUtils.logger, 'info');

sessionStorage.clear();
clearSession(replay);
replay['_initializeSessionForSampling']();
Expand All @@ -422,32 +424,18 @@ describe('Integration | flush', () => {
// no checkout!
await advanceTimers(DEFAULT_FLUSH_MIN_DELAY);

expect(mockFlush).toHaveBeenCalledTimes(1);
expect(mockSendReplay).toHaveBeenCalledTimes(1);

const replayData = mockSendReplay.mock.calls[0][0];
// No flush is scheduled is aborted because event is after maxReplayDuration
expect(mockFlush).toHaveBeenCalledTimes(0);
expect(mockSendReplay).toHaveBeenCalledTimes(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_REPLAY_DURATION + 100
} because it is after maxReplayDuration`,
},
},
},
]);
expect(spyLogger).toHaveBeenLastCalledWith(
`[Replay] Skipping event with timestamp ${
BASE_TIMESTAMP + MAX_REPLAY_DURATION + 100
} because it is after maxReplayDuration`,
);

replay.getOptions()._experiments.traceInternals = false;
spyLogger.mockRestore();
});

/**
Expand Down
65 changes: 63 additions & 2 deletions packages/replay/test/unit/util/addEvent.test.ts
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
import 'jsdom-worker';

import { BASE_TIMESTAMP } from '../..';
import { REPLAY_MAX_EVENT_BUFFER_SIZE } from '../../../src/constants';
import { MAX_REPLAY_DURATION, REPLAY_MAX_EVENT_BUFFER_SIZE, SESSION_IDLE_PAUSE_DURATION } from '../../../src/constants';
import type { EventBufferProxy } from '../../../src/eventBuffer/EventBufferProxy';
import { addEvent } from '../../../src/util/addEvent';
import { addEvent, shouldAddEvent } from '../../../src/util/addEvent';
import { getTestEventIncremental } from '../../utils/getTestEvent';
import { setupReplayContainer } from '../../utils/setupReplayContainer';
import { useFakeTimers } from '../../utils/use-fake-timers';
Expand Down Expand Up @@ -57,4 +57,65 @@ describe('Unit | util | addEvent', () => {

expect(replay.isEnabled()).toEqual(false);
});

describe('shouldAddEvent', () => {
beforeEach(() => {
jest.setSystemTime(BASE_TIMESTAMP);
});

it('returns true by default', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP });

expect(shouldAddEvent(replay, event)).toEqual(true);
});

it('returns false when paused', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP });

replay.pause();

expect(shouldAddEvent(replay, event)).toEqual(false);
});

it('returns false when disabled', async () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP });

await replay.stop();

expect(shouldAddEvent(replay, event)).toEqual(false);
});

it('returns false if there is no eventBuffer', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP });

replay.eventBuffer = null;

expect(shouldAddEvent(replay, event)).toEqual(false);
});

it('returns false when event is too old', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP - SESSION_IDLE_PAUSE_DURATION - 1 });

expect(shouldAddEvent(replay, event)).toEqual(false);
});

it('returns false if event is too long after initial timestamp', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP + MAX_REPLAY_DURATION + 1 });

expect(shouldAddEvent(replay, event)).toEqual(false);
});

it('returns true if event is withing max duration after after initial timestamp', () => {
const replay = setupReplayContainer({});
const event = getTestEventIncremental({ timestamp: BASE_TIMESTAMP + MAX_REPLAY_DURATION - 1 });

expect(shouldAddEvent(replay, event)).toEqual(true);
});
});
});
4 changes: 2 additions & 2 deletions packages/replay/test/unit/util/handleRecordingEmit.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,8 @@ describe('Unit | util | handleRecordingEmit', () => {

beforeEach(function () {
jest.setSystemTime(BASE_TIMESTAMP);
addEventMock = jest.spyOn(SentryAddEvent, 'addEvent').mockImplementation(async () => {
// Do nothing
addEventMock = jest.spyOn(SentryAddEvent, 'addEventSync').mockImplementation(() => {
return true;
});
});

Expand Down