diff --git a/CHANGELOG.md b/CHANGELOG.md index ccadcd59b3a..e703a96c2ca 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,9 @@ - Stop blocking the main thread while the frame metrics thread starts when the first activity transaction begins ([#6500](https://github.com/getsentry/sentry-java/pull/6500)) - On a busy device during cold start this could stall the launcher activity's `onCreate` for hundreds of milliseconds. - Do not inspect the response body of streaming Apollo 3 and 4 responses (`multipart/mixed`, `text/event-stream`) for failed requests, which blocked `@defer` and `@stream` ([#6432](https://github.com/getsentry/sentry-java/pull/6432)) +- Session Replay no longer drops or freezes video when the device clock changes mid-recording ([#6542](https://github.com/getsentry/sentry-java/pull/6542)) + - The replay shows the change once, as a gap or an overlap, and breadcrumbs and errors stay aligned with the video. + - A forward change longer than the session duration (1h) ends a full-session recording, as reaching that duration does. When recording only for errors, what was recorded before such a change is dropped, so the replay of a later error starts after it. ### Dependencies diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BaseCaptureStrategy.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BaseCaptureStrategy.kt index b6b8981f8ce..a2e34e2200f 100644 --- a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BaseCaptureStrategy.kt +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BaseCaptureStrategy.kt @@ -35,10 +35,14 @@ import io.sentry.android.replay.gestures.ReplayGestureConverter import io.sentry.android.replay.util.ReplayRunnable import io.sentry.protocol.SentryId import io.sentry.rrweb.RRWebEvent +import io.sentry.time.AnchoredClock import io.sentry.time.Deadline import io.sentry.time.MonotonicTicker +import io.sentry.time.Timestamp import io.sentry.transport.ICurrentDateProvider +import io.sentry.util.AutoClosableReentrantLock import java.io.File +import java.util.ArrayDeque import java.util.Date import java.util.Deque import java.util.concurrent.ConcurrentLinkedDeque @@ -56,12 +60,14 @@ internal abstract class BaseCaptureStrategy constructor( private val options: SentryOptions, private val scopes: IScopes?, - // TODO [v9]: We should consider replacing this with AnchoredClock in V9. + // TODO [v9]: Remove ICurrentDateProvider and anchor on options.epochClock (JAVA-827). dateProvider: ICurrentDateProvider, private val ticker: MonotonicTicker, protected val replayExecutor: ScheduledExecutorService, protected val persistingExecutor: ScheduledExecutorService, private val replayCacheProvider: ((replayId: SentryId) -> ReplayCache)? = null, + /** The timeline of the recording this strategy takes over, if it continues one. */ + continuedTimeline: AnchoredClock? = null, ) : CaptureStrategy { internal companion object { private const val TAG = "CaptureStrategy" @@ -69,7 +75,30 @@ constructor( private const val MAX_CONTEXT_VALUES = 100 } - private val gestureConverter = ReplayGestureConverter(dateProvider, ticker) + protected val clock = + ReplayClock( + { Timestamp.ofEpochNanos(DateUtils.millisToNanos(dateProvider.currentTimeMillis)) }, + ticker, + continuedTimeline, + ) + + /** + * Makes moving onto a new timeline atomic: checking the wall clock, restarting the clock and + * draining [currentEvents] for the segment that closes the old timeline happen together. Touch + * events are stamped and added under it too. So two frames can't both follow one jump, and every + * touch event stamped on the old timeline is drained while every one stamped on the new one + * stays. + */ + private val timelineLock = AutoClosableReentrantLock() + + /** + * The timeline the work queued on [replayExecutor] is on: the frames it stored and the segment it + * is building. Only [stampFrame] restarts the clock, and that frame's task moves this onto the + * new timeline, so the two differ only while such a task is queued. + */ + @Volatile protected var executorTimeline: AnchoredClock = clock.timeline + + private val gestureConverter = ReplayGestureConverter({ clock.nowMillis() }, ticker) protected val isTerminating = AtomicBoolean(false) protected var cache: ReplayCache? = null @@ -132,7 +161,7 @@ constructor( this.currentSegment = segmentId this.replayType = replayType ?: (if (this is SessionCaptureStrategy) SESSION else BUFFER) - segmentTimestamp = DateUtils.getCurrentDateTime() + segmentTimestamp = DateUtils.getDateTime(clock.nowMillis()) replayDeadline = Deadline.after(ticker, options.sessionReplay.sessionDuration, MILLISECONDS) // the same values MainEventProcessor applies to current-run segments recordingMetadata = @@ -150,7 +179,9 @@ constructor( } override fun resume() { - val resumedAt = DateUtils.getCurrentDateTime() + // not re-anchored here: that would make every segment request until the task below runs look + // like it raced a jump. The first frame after a jump while paused follows it like any other. + val resumedAt = DateUtils.getDateTime(clock.nowMillis()) // Keep the timeline update behind queued frames and pause/flush segment creation. replayExecutor.submit(ReplayRunnable("$TAG.resume") { segmentTimestamp = resumedAt }) } @@ -216,11 +247,38 @@ constructor( this.recorderConfig = recorderConfig } + /** + * Stamps a frame captured now. If the wall clock jumped since the previous frame, the recording + * first moves onto a new timeline anchored on it, unless the jump is forward by more than + * [maxForwardJumpMillis]. + */ + protected fun stampFrame(maxForwardJumpMillis: Long = Long.MAX_VALUE): StampedFrame = + timelineLock.acquire().use { + val jumpMillis = clock.wallClockJumpMillis() + if (jumpMillis == 0L || jumpMillis > maxForwardJumpMillis) { + StampedFrame(clock.nowMillis(), jumpedTooFar = jumpMillis > maxForwardJumpMillis) + } else { + val oldTimeline = clock.timeline + val oldTimelineEnd = oldTimeline.nowMillis() + val newTimeline = clock.restart() + val oldEvents = ArrayDeque() + var event = currentEvents.pollFirst() + while (event != null) { + oldEvents.add(event) + event = currentEvents.pollFirst() + } + val jump = TimelineJump(oldTimeline, oldTimelineEnd, newTimeline, oldEvents) + StampedFrame(jump.newTimelineStart, jump) + } + } + override fun onTouchEvent(event: MotionEvent) { recorderConfig?.let { config -> - val rrwebEvents = gestureConverter.convert(event, config) - if (rrwebEvents != null) { - currentEvents += rrwebEvents + timelineLock.acquire().use { + val rrwebEvents = gestureConverter.convert(event, config) + if (rrwebEvents != null) { + currentEvents += rrwebEvents + } } } } @@ -245,6 +303,46 @@ constructor( } } + protected class StampedFrame( + val timestamp: Long, + /** Set when the recording moved onto a new timeline at this frame. */ + val jump: TimelineJump? = null, + /** The wall clock jumped forward too far to follow, so the frame stayed on the old timeline. */ + val jumpedTooFar: Boolean = false, + ) + + /** + * Where the old timeline ended and the new one starts, and the touch events stamped on the old + * one, which belong to the segment that closes it. + */ + protected class TimelineJump( + val oldTimeline: AnchoredClock, + val oldTimelineEnd: Long, + val newTimeline: AnchoredClock, + val oldEvents: Deque, + ) { + val newTimelineStart: Long = newTimeline.startTime().epochMillis + } + + /** + * The times a segment request reads when it is made, so a busy executor doesn't stretch the + * segment. If a frame moved the recording onto a new timeline in between, what the request read + * and the frames its task finds are on different timelines, so the task reads again with [read] + * on the timeline the queued work is on. + */ + protected inner class SegmentRequest(private val read: (AnchoredClock) -> T) { + // null while the task of a frame that followed a jump is still queued: the clock is on the new + // timeline already, the frames are not + private val timeline = clock.timeline.takeIf { it === executorTimeline } + private val requested = timeline?.let(read) + + /** Called from the request's task: the times to use, and the timeline they are on. */ + fun resolve(): Pair { + val current = executorTimeline + return (requested?.takeIf { timeline === current } ?: read(current)) to current + } + } + private inline fun persistableAtomicNullable( initialValue: T? = null, propertyName: String, diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BufferCaptureStrategy.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BufferCaptureStrategy.kt index 071acc19cae..4395e8a0956 100644 --- a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BufferCaptureStrategy.kt +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/BufferCaptureStrategy.kt @@ -20,6 +20,7 @@ import io.sentry.android.replay.capture.CaptureStrategy.ReplaySegment import io.sentry.android.replay.util.ReplayRunnable import io.sentry.clientreport.DiscardReason.RATELIMIT_BACKOFF import io.sentry.protocol.SentryId +import io.sentry.time.AnchoredClock import io.sentry.time.MonotonicTicker import io.sentry.transport.ICurrentDateProvider import java.io.File @@ -62,7 +63,7 @@ constructor( ) { // TODO: capture envelopes for buffered segments instead, but don't send them until buffer is // triggered - private val bufferedSegments = mutableListOf() + private val bufferedSegments = mutableListOf() internal companion object { private const val TAG = "BufferCaptureStrategy" @@ -70,13 +71,7 @@ constructor( } override fun pause() { - createCurrentSegment("pause") { segment -> - if (segment is ReplaySegment.Created) { - bufferedSegments += segment - - currentSegment++ - } - } + createCurrentSegment("pause") { segment, timeline -> buffer(segment, timeline) } super.pause() } @@ -114,7 +109,7 @@ constructor( return } - createCurrentSegment("capture_replay") { segment -> + createCurrentSegment("capture_replay") { segment, _ -> bufferedSegments.capture() if (segment is ReplaySegment.Created) { @@ -135,27 +130,69 @@ constructor( ) { // have to do it before submitting, otherwise if the queue is busy, the timestamp won't be // reflecting the exact time of when it was captured - val frameTimestamp = dateProvider.currentTimeMillis + val currentConfig = recorderConfig + val frame = stampFrame() + // a later frame may move the clock onto a new timeline before this task runs + val bufferLimit = frame.timestamp - options.sessionReplay.errorReplayDuration replayExecutor.submit( ReplayRunnable("$TAG.add_frame") { - cache?.store(frameTimestamp) + // first, so the old timeline is encoded and rotated without this frame + frame.jump?.let { followJump(it, currentConfig) } + cache?.store(frame.timestamp) - val now = dateProvider.currentTimeMillis - val bufferLimit = now - options.sessionReplay.errorReplayDuration screenAtStart = cache?.rotate(bufferLimit) - bufferedSegments.rotate(bufferLimit) + bufferedSegments.rotate() } ) } - override fun onConfigurationChanged(recorderConfig: ScreenshotRecorderConfig) { - createCurrentSegment("configuration_changed") { segment -> - if (segment is ReplaySegment.Created) { - bufferedSegments += segment + /** + * Moves the buffer onto the new timeline. What was recorded before the jump stays buffered, as a + * segment of its own, unless the clock jumped forward by more than the session duration. + */ + private fun followJump(jump: TimelineJump, currentConfig: ScreenshotRecorderConfig?) { + if (jump.newTimelineStart - jump.oldTimelineEnd > options.sessionReplay.sessionDuration) { + // an error soon after would send one replay spanning the jump, hours or years long; session + // mode stops at the same jump instead + bufferedSegments.discardWhere { true } + } else { + bufferOldTimeline(jump, currentConfig) + } + // frames left from the old timeline would be encoded into the new one's segments + cache?.rotate(until = jump.oldTimelineEnd) + // last, so a segment request can't see the new timeline before the cache is on it + executorTimeline = jump.newTimeline + } - currentSegment++ - } + /** Buffers the frames up to where the old timeline ended as a segment of their own. */ + private fun bufferOldTimeline(jump: TimelineJump, currentConfig: ScreenshotRecorderConfig?) { + val firstFrameTimestamp = cache?.firstFrameTimestamp() + if (!isTerminating.get() && currentConfig != null && firstFrameTimestamp != null) { + val segment = + createSegmentInternal( + jump.oldTimelineEnd - firstFrameTimestamp, + DateUtils.getDateTime(firstFrameTimestamp), + currentReplayId, + currentSegment, + currentConfig.recordingHeight, + currentConfig.recordingWidth, + currentConfig.frameRate, + currentConfig.bitRate, + events = jump.oldEvents, + ) + buffer(segment, jump.oldTimeline) } + } + + private fun buffer(segment: ReplaySegment, timeline: AnchoredClock) { + if (segment is ReplaySegment.Created) { + bufferedSegments += BufferedSegment(segment, timeline) + currentSegment++ + } + } + + override fun onConfigurationChanged(recorderConfig: ScreenshotRecorderConfig) { + createCurrentSegment("configuration_changed") { segment, timeline -> buffer(segment, timeline) } super.onConfigurationChanged(recorderConfig) } @@ -175,7 +212,7 @@ constructor( return this } // we hand over replayExecutor and persistingExecutor to the new strategy to preserve order of - // execution + // execution, and the timeline, which the segments about to be flushed are on val captureStrategy = SessionCaptureStrategy( options, @@ -184,6 +221,7 @@ constructor( ticker, replayExecutor, persistingExecutor, + continuedTimeline = clock.timeline, ) captureStrategy.recorderConfig = recorderConfig captureStrategy.start( @@ -196,7 +234,7 @@ constructor( override fun onTouchEvent(event: MotionEvent) { super.onTouchEvent(event) - val bufferLimit = dateProvider.currentTimeMillis - options.sessionReplay.errorReplayDuration + val bufferLimit = clock.nowMillis() - options.sessionReplay.errorReplayDuration rotateEvents(currentEvents, bufferLimit) } @@ -218,10 +256,10 @@ constructor( } } - private fun MutableList.capture() { + private fun MutableList.capture() { var bufferedSegment = removeFirstOrNull() while (bufferedSegment != null) { - bufferedSegment.capture(scopes) + bufferedSegment.segment.capture(scopes) bufferedSegment = removeFirstOrNull() // a short delay between processing envelopes to avoid bursting our server and hitting // another rate limit https://develop.sentry.dev/sdk/features/#additional-capabilities @@ -230,15 +268,18 @@ constructor( } } - private fun MutableList.rotate(bufferLimit: Long) { + private fun MutableList.rotate() = + // it can be that the buffered segment is half-way older than the buffer limit, but + // we only drop it if its end timestamp is older + discardWhere { it.endedMoreThan(options.sessionReplay.errorReplayDuration) } + + private fun MutableList.discardWhere(predicate: (BufferedSegment) -> Boolean) { // TODO: can be a single while-loop var removed = false removeAll { - // it can be that the buffered segment is half-way older than the buffer limit, but - // we only drop it if its end timestamp is older - if (it.replay.timestamp.time < bufferLimit) { + if (predicate(it)) { currentSegment-- - deleteFile(it.replay.videoFile) + deleteFile(it.segment.replay.videoFile) removed = true return@removeAll true } @@ -246,11 +287,26 @@ constructor( } if (removed) { // shift segmentIds after rotating buffered segments - forEachIndexed { index, segment -> segment.setSegmentId(index) } + forEachIndexed { index, buffered -> buffered.segment.setSegmentId(index) } } } - private fun createCurrentSegment(taskName: String, onSegmentCreated: (ReplaySegment) -> Unit) { + /** + * A segment held for the next error, with the timeline it was stamped on, so it ages by the time + * that passed even after the recording moved onto another timeline. + */ + private class BufferedSegment( + val segment: ReplaySegment.Created, + private val timeline: AnchoredClock, + ) { + fun endedMoreThan(millis: Long): Boolean = + timeline.nowMillis() - segment.replay.timestamp.time > millis + } + + private fun createCurrentSegment( + taskName: String, + onSegmentCreated: (segment: ReplaySegment, timeline: AnchoredClock) -> Unit, + ) { val currentConfig = recorderConfig if (currentConfig == null) { options.logger.log( @@ -259,18 +315,13 @@ constructor( ) return } - val errorReplayDuration = options.sessionReplay.errorReplayDuration - val now = dateProvider.currentTimeMillis - val currentSegmentTimestamp = - cache?.firstFrameTimestamp()?.let { - // in buffer mode we have to set the timestamp of the first frame as the actual start - DateUtils.getDateTime(it) - } ?: DateUtils.getDateTime(now - errorReplayDuration) - val duration = now - currentSegmentTimestamp.time + val request = SegmentRequest { wholeBuffer(it) } val replayId = currentReplayId replayExecutor.submit( ReplayRunnable("$TAG.$taskName") { + val (window, timeline) = request.resolve() + val (currentSegmentTimestamp, duration) = window val segment = createSegmentInternal( duration, @@ -282,8 +333,19 @@ constructor( currentConfig.frameRate, currentConfig.bitRate, ) - onSegmentCreated(segment) + onSegmentCreated(segment, timeline) } ) } + + /** The start and duration of a segment of the whole buffer, up to now on [timeline]. */ + private fun wholeBuffer(timeline: AnchoredClock): Pair { + val now = timeline.nowMillis() + val start = + cache?.firstFrameTimestamp()?.let { + // in buffer mode we have to set the timestamp of the first frame as the actual start + DateUtils.getDateTime(it) + } ?: DateUtils.getDateTime(now - options.sessionReplay.errorReplayDuration) + return start to now - start.time + } } diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/ReplayClock.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/ReplayClock.kt new file mode 100644 index 00000000000..cc4fc572c48 --- /dev/null +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/ReplayClock.kt @@ -0,0 +1,60 @@ +package io.sentry.android.replay.capture + +import io.sentry.time.AnchoredClock +import io.sentry.time.EpochClock +import io.sentry.time.MonotonicTicker +import io.sentry.time.Timestamp +import java.util.concurrent.TimeUnit.NANOSECONDS +import kotlin.math.abs + +/** + * The timeline a recording stamps its frames, segments and touch events on. + * + * Those stamps are subtracted from each other: a segment is the frames within 5s of its start, and + * the buffer is the last 30s. So they come from one [AnchoredClock], where a wall-clock change + * can't drop frames or freeze the video. Breadcrumbs, errors and spans, though, are stamped from + * the wall clock elsewhere in the SDK, and the player places them on the video by that stamp. So + * the timeline must not drift away from the wall clock either: when [wallClockJumpMillis] reports a + * jump, the recording closes the segment on the current timeline and [restart]s on the wall clock. + * + * Reads are safe from any thread. Checking for a jump and then restarting is a check-then-act, so + * [BaseCaptureStrategy] does both under its timeline lock. + */ +internal class ReplayClock( + private val epochClock: EpochClock, + private val ticker: MonotonicTicker, + continued: AnchoredClock? = null, +) { + internal companion object { + // just under the 1.1s the player shows as a gap in the video + const val JUMP_TOLERANCE_MS = 1000L + } + + /** The current timeline. [restart] replaces it, so a reference read once stays consistent. */ + @Volatile + var timeline: AnchoredClock = continued ?: AnchoredClock.create(epochClock, ticker) + private set + + fun nowMillis(): Long = timeline.nowMillis() + + /** Anchors a new timeline on the wall clock and returns it. */ + fun restart(): AnchoredClock { + val next = AnchoredClock.create(epochClock, ticker) + timeline = next + return next + } + + /** + * How far the wall clock has jumped away from the timeline, positive when it moved forward, or + * `0` while the two agree within [JUMP_TOLERANCE_MS]. + */ + fun wallClockJumpMillis(): Long { + val jump = epochClock.now().epochMillis - nowMillis() + return if (abs(jump) > JUMP_TOLERANCE_MS) jump else 0 + } +} + +internal val Timestamp.epochMillis: Long + get() = NANOSECONDS.toMillis(epochNanos()) + +internal fun AnchoredClock.nowMillis(): Long = now().epochMillis diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/SessionCaptureStrategy.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/SessionCaptureStrategy.kt index 8e6ae9fc4a4..776e6ae55f4 100644 --- a/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/SessionCaptureStrategy.kt +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/capture/SessionCaptureStrategy.kt @@ -1,6 +1,7 @@ package io.sentry.android.replay.capture import android.graphics.Bitmap +import io.sentry.DateUtils import io.sentry.IScopes import io.sentry.SentryLevel.DEBUG import io.sentry.SentryLevel.INFO @@ -11,6 +12,7 @@ import io.sentry.android.replay.ScreenshotRecorderConfig import io.sentry.android.replay.capture.CaptureStrategy.ReplaySegment import io.sentry.android.replay.util.ReplayRunnable import io.sentry.protocol.SentryId +import io.sentry.time.AnchoredClock import io.sentry.time.MonotonicTicker import io.sentry.transport.ICurrentDateProvider import java.util.Date @@ -33,11 +35,12 @@ internal class SessionCaptureStrategy constructor( private val options: SentryOptions, private val scopes: IScopes?, - private val dateProvider: ICurrentDateProvider, + dateProvider: ICurrentDateProvider, ticker: MonotonicTicker, executor: ScheduledExecutorService, persistingExecutor: ScheduledExecutorService, replayCacheProvider: ((replayId: SentryId) -> ReplayCache)? = null, + continuedTimeline: AnchoredClock? = null, ) : BaseCaptureStrategy( options, @@ -47,6 +50,7 @@ constructor( executor, persistingExecutor, replayCacheProvider, + continuedTimeline, ) { internal companion object { private const val TAG = "SessionCaptureStrategy" @@ -114,10 +118,14 @@ constructor( // have to do it before submitting, otherwise if the queue is busy, the timestamp won't be // reflecting the exact time of when it was captured val currentConfig = recorderConfig - val frameTimestamp = dateProvider.currentTimeMillis - val deadlineExceeded = replayDeadline?.hasPassed() == true + val frame = stampFrame(maxForwardJumpMillis = options.sessionReplay.sessionDuration) + val frameTimestamp = frame.timestamp + // a recording can't span a forward jump longer than its cap, so one ends it like the cap does + val deadlineExceeded = replayDeadline?.hasPassed() == true || frame.jumpedTooFar replayExecutor.submit( ReplayRunnable("$TAG.add_frame") { + // first, so the old timeline is encoded and rotated without this frame + frame.jump?.let { followJump(it, currentConfig) } cache?.store(frameTimestamp) val currentSegmentTimestamp = segmentTimestamp @@ -171,6 +179,37 @@ constructor( ) } + /** + * Captures the segment up to where the old timeline ended, and starts the next on the new one. + */ + private fun followJump(jump: TimelineJump, currentConfig: ScreenshotRecorderConfig?) { + val currentSegmentTimestamp = segmentTimestamp + if (currentSegmentTimestamp != null) { + if (!isTerminating.get() && currentConfig != null) { + val segment = + createSegmentInternal( + jump.oldTimelineEnd - currentSegmentTimestamp.time, + currentSegmentTimestamp, + currentReplayId, + currentSegment, + currentConfig.recordingHeight, + currentConfig.recordingWidth, + currentConfig.frameRate, + currentConfig.bitRate, + events = jump.oldEvents, + ) + if (segment is ReplaySegment.Created) { + segment.capture(scopes) + currentSegment++ + } + } + segmentTimestamp = DateUtils.getDateTime(jump.newTimelineStart) + } + // frames left from the old timeline would be encoded into the new one's segments + cache?.rotate(until = jump.oldTimelineEnd) + executorTimeline = jump.newTimeline + } + override fun onConfigurationChanged(recorderConfig: ScreenshotRecorderConfig) { createCurrentSegment("onConfigurationChanged") { segment -> if (segment is ReplaySegment.Created) { @@ -198,13 +237,14 @@ constructor( return } - val requestedAt = dateProvider.currentTimeMillis + val request = SegmentRequest { it.nowMillis() } val replayId = currentReplayId replayExecutor.submit( ReplayRunnable("$TAG.$taskName") { // Keep the request time so executor delays do not extend the segment, but read the mutable // timeline here so a queued natural boundary cannot make it stale. val currentSegmentTimestamp = segmentTimestamp ?: return@ReplayRunnable + val requestedAt = request.resolve().first val segment = createSegmentInternal( requestedAt - currentSegmentTimestamp.time, diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationTest.kt index 70e8426d124..a58a4f4a7cd 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationTest.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationTest.kt @@ -1505,10 +1505,7 @@ class ReplayIntegrationTest { BufferCaptureStrategy( fixture.options, fixture.scopes, - // make time jump so session strategy will immediately cut a segment on next frame - ICurrentDateProvider { - System.currentTimeMillis() + fixture.options.sessionReplay.sessionSegmentDuration - }, + CurrentDateProvider.getInstance(), fixture.options.monotonicTicker, // run tasks synchronously in tests mock { diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationWithRecorderTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationWithRecorderTest.kt index 44f1551ede2..fcd91a646e4 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationWithRecorderTest.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayIntegrationWithRecorderTest.kt @@ -18,10 +18,13 @@ import io.sentry.android.replay.ReplayIntegrationWithRecorderTest.LifecycleState import io.sentry.android.replay.util.ReplayShadowMediaCodec import io.sentry.rrweb.RRWebMetaEvent import io.sentry.rrweb.RRWebVideoEvent +import io.sentry.time.MonotonicTicker +import io.sentry.time.TestMonotonicTicker import io.sentry.transport.CurrentDateProvider import io.sentry.transport.ICurrentDateProvider import io.sentry.util.thread.NoOpThreadChecker import java.io.File +import java.util.concurrent.TimeUnit.MILLISECONDS import java.util.concurrent.atomic.AtomicBoolean import kotlin.test.BeforeTest import kotlin.test.assertEquals @@ -45,7 +48,12 @@ class ReplayIntegrationWithRecorderTest { @get:Rule val tmpDir = TemporaryFolder() internal class Fixture { - val options = SentryOptions().apply { threadChecker = NoOpThreadChecker.getInstance() } + val ticker = TestMonotonicTicker() + val options = + object : SentryOptions() { + override fun getMonotonicTicker(): MonotonicTicker = ticker + } + .apply { threadChecker = NoOpThreadChecker.getInstance() } val scopes = mock() fun getSut( @@ -83,11 +91,8 @@ class ReplayIntegrationWithRecorderTest { fun `works with different recorder`() { val captured = AtomicBoolean(false) whenever(fixture.scopes.captureReplay(any(), anyOrNull())).then { captured.set(true) } - // fake current time to trigger segment creation, CurrentDateProvider.getInstance() should - // be used in prod - val dateProvider = ICurrentDateProvider { - System.currentTimeMillis() + fixture.options.sessionReplay.sessionSegmentDuration - } + var now = System.currentTimeMillis() + val dateProvider = ICurrentDateProvider { now } fixture.options.sessionReplay.isTrackConfiguration = false fixture.options.sessionReplay.sessionSampleRate = 1.0 @@ -165,6 +170,9 @@ class ReplayIntegrationWithRecorderTest { val flutterConfig = ScreenshotRecorderConfig(100, 200, 1f, 1f, 1, 20_000) replay.onConfigurationChanged(flutterConfig) + // a whole segment later, so the frame closes it + now += fixture.options.sessionReplay.sessionSegmentDuration + fixture.ticker.advance(fixture.options.sessionReplay.sessionSegmentDuration, MILLISECONDS) replay.onScreenshotRecorded(screenshot, frameTimestamp = 1) // verify diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/BufferCaptureStrategyTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/BufferCaptureStrategyTest.kt index f3830bc1ed5..e1c4b04e98e 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/BufferCaptureStrategyTest.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/BufferCaptureStrategyTest.kt @@ -2,7 +2,9 @@ package io.sentry.android.replay.capture import android.graphics.Bitmap import android.view.MotionEvent +import com.google.common.truth.Truth.assertThat import io.sentry.DataCategory +import io.sentry.Hint import io.sentry.IScopes import io.sentry.Scope import io.sentry.ScopeCallback @@ -10,6 +12,7 @@ import io.sentry.ScopeType import io.sentry.SentryEnvelope import io.sentry.SentryEnvelopeHeader import io.sentry.SentryOptions +import io.sentry.SentryReplayEvent import io.sentry.SentryReplayEvent.ReplayType import io.sentry.android.replay.DefaultReplayBreadcrumbConverter import io.sentry.android.replay.GeneratedVideo @@ -24,11 +27,16 @@ import io.sentry.android.replay.capture.BufferCaptureStrategyTest.Fixture.Compan import io.sentry.clientreport.DiscardReason import io.sentry.clientreport.DiscardedEvent import io.sentry.protocol.SentryId +import io.sentry.rrweb.RRWebEvent +import io.sentry.rrweb.RRWebInteractionEvent +import io.sentry.rrweb.RRWebInteractionEvent.InteractionType import io.sentry.time.TestMonotonicTicker -import io.sentry.transport.CurrentDateProvider import io.sentry.transport.ICurrentDateProvider import io.sentry.transport.RateLimiter import java.io.File +import java.util.concurrent.ScheduledExecutorService +import java.util.concurrent.TimeUnit.DAYS +import java.util.concurrent.TimeUnit.MILLISECONDS import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse @@ -40,6 +48,7 @@ import org.mockito.ArgumentMatchers.anyInt import org.mockito.ArgumentMatchers.anyLong import org.mockito.kotlin.any import org.mockito.kotlin.anyOrNull +import org.mockito.kotlin.argumentCaptor import org.mockito.kotlin.doAnswer import org.mockito.kotlin.eq import org.mockito.kotlin.mock @@ -113,11 +122,79 @@ class BufferCaptureStrategyTest { ?.discardedEvents .orEmpty() + var now = System.currentTimeMillis() val ticker = TestMonotonicTicker() + /** Time passing: the wall clock and the ticker move together. */ + fun elapse(millis: Long) { + now += millis + ticker.advance(millis, MILLISECONDS) + } + + /** The device clock being changed: only the wall clock moves. */ + fun jumpWallClock(millis: Long) { + now += millis + } + + /** + * Makes [replayCache] keep the frame timestamps added to the returned list, so segments start + * at the first frame and last as long as requested. Their videos are written to [videoDir]. + */ + fun storeFrames(videoDir: File? = null): MutableList { + val frames = mutableListOf() + whenever(replayCache.firstFrameTimestamp()).thenAnswer { frames.firstOrNull() } + whenever(replayCache.rotate(anyLong())).thenAnswer { invocation -> + frames.removeAll { it < invocation.getArgument(0) } + null + } + whenever( + replayCache.createVideoOf( + anyLong(), + anyLong(), + anyInt(), + anyInt(), + anyInt(), + anyInt(), + anyInt(), + any(), + ) + ) + .thenAnswer { + val video = File(videoDir, "${it.arguments[2]}.mp4") + videoDir?.let { video.writeText("video") } + GeneratedVideo(video, 1, it.arguments[0] as Long) + } + return frames + } + + private val queuedTasks = ArrayDeque() + + /** Holds submitted tasks until [runQueuedTasks], like a busy replay executor. */ + val queuedExecutor = + mock { + doAnswer { + queuedTasks += it.arguments[0] as Runnable + null + } + .whenever(mock) + .submit(any()) + } + + fun runQueuedTasks() { + while (queuedTasks.isNotEmpty()) { + queuedTasks.removeFirst().run() + } + } + fun getSut( - dateProvider: ICurrentDateProvider = CurrentDateProvider.getInstance(), + dateProvider: ICurrentDateProvider = ICurrentDateProvider { now }, replayCacheDir: File? = null, + replayExecutor: ScheduledExecutorService = mock { + whenever(it.submit(any())).doAnswer { invocation -> + (invocation.arguments[0] as Runnable).run() + null + } + }, ): BufferCaptureStrategy { replayCacheDir?.let { whenever(replayCache.replayCacheDir).thenReturn(it) } return BufferCaptureStrategy( @@ -125,12 +202,7 @@ class BufferCaptureStrategyTest { scopes, dateProvider, ticker, - mock { - whenever(it.submit(any())).doAnswer { invocation -> - (invocation.arguments[0] as Runnable).run() - null - } - }, + replayExecutor, mock { whenever(it.submit(any())).doAnswer { invocation -> (invocation.arguments[0] as Runnable).run() @@ -465,4 +537,187 @@ class BufferCaptureStrategyTest { "the current replay cache folder is not being deleted.", ) } + + /** The recording payload of every captured segment, in capture order, with its segment id. */ + private fun capturedSegments(count: Int): List>> { + val events = argumentCaptor() + val hints = argumentCaptor() + verify(fixture.scopes, times(count)).captureReplay(events.capture(), hints.capture()) + return events.allValues.zip(hints.allValues.map { it.replayRecording!!.payload!! }) + } + + @Test + fun `a backward wall-clock jump buffers the frames before it as a segment of their own`() { + val frames = fixture.storeFrames() + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(3_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(2_000) + + strategy.captureReplay(false) {} + + val segments = capturedSegments(count = 2).map { it.first } + assertThat(segments.map { it.segmentId }).containsExactly(0, 1).inOrder() + assertThat(segments.map { it.replayStartTimestamp!!.time }) + .containsExactly(segmentStart, newTimelineStart) + .inOrder() + assertThat(segments.map { it.timestamp!!.time - it.replayStartTimestamp!!.time }) + .containsExactly(3_000L, 2_000L) + .inOrder() + } + + @Test + fun `the segment buffered at a forward wall-clock jump ages by the time that passed`() { + val frames = fixture.storeFrames() + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(3_000) + fixture.jumpWallClock(120_000) + + strategy.onScreenshotRecorded(mock()) { frames += it } + assertThat(strategy.currentSegment).isEqualTo(1) + + fixture.elapse(fixture.options.sessionReplay.errorReplayDuration) + strategy.onScreenshotRecorded(mock()) { frames += it } + assertThat(strategy.currentSegment).isEqualTo(1) + + fixture.elapse(1) + strategy.onScreenshotRecorded(mock()) { frames += it } + assertThat(strategy.currentSegment).isEqualTo(0) + } + + @Test + fun `touch events stay with the timeline they were stamped on`() { + val frames = fixture.storeFrames() + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(1_000) + strategy.onTouchEvent(fixture.mockedMotionEvent(MotionEvent.ACTION_DOWN)) + fixture.elapse(2_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(1_000) + strategy.onTouchEvent(fixture.mockedMotionEvent(MotionEvent.ACTION_UP)) + fixture.elapse(1_000) + + strategy.captureReplay(false) {} + + val touches = + capturedSegments(count = 2).map { (_, payload) -> + payload.filterIsInstance().map { it.interactionType to it.timestamp } + } + assertThat(touches[0]).containsExactly(InteractionType.TouchStart to segmentStart + 1_000) + assertThat(touches[1]).containsExactly(InteractionType.TouchEnd to newTimelineStart + 1_000) + } + + @Test + fun `convert continues the buffer's timeline`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.elapse(1_000) + // not seen by any frame yet, so the converted strategy must still notice it + fixture.jumpWallClock(10_000) + + val converted = strategy.convert() + + assertThat(converted.segmentTimestamp!!.time).isEqualTo(segmentStart + 1_000) + converted.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(fixture.now) } + assertThat(converted.segmentTimestamp!!.time).isEqualTo(fixture.now) + } + + @Test + fun `follows a forward wall-clock jump longer than the session duration`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(1_000) + fixture.jumpWallClock(fixture.options.sessionReplay.sessionDuration * 2) + + strategy.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(fixture.now) } + + verify(fixture.options.replayController, never()).stop() + } + + @Test + fun `a forward wall-clock jump longer than the session duration drops what was buffered before it`() { + val videoDir = tmpDir.newFolder() + val frames = fixture.storeFrames(videoDir) + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(2_000) + strategy.onConfigurationChanged(fixture.recorderConfig.copy(recordingWidth = 720)) + assertThat(strategy.currentSegment).isEqualTo(1) + fixture.elapse(1_000) + strategy.onScreenshotRecorded(mock()) { frames += it } + strategy.onTouchEvent(fixture.mockedMotionEvent(MotionEvent.ACTION_DOWN)) + fixture.elapse(1_000) + fixture.jumpWallClock(fixture.options.sessionReplay.sessionDuration * 2) + val newTimelineStart = fixture.now + + strategy.onScreenshotRecorded(mock()) { frames += it } + + assertThat(strategy.currentSegment).isEqualTo(0) + assertThat(File(videoDir, "0.mp4").exists()).isFalse() + assertThat(frames).containsExactly(newTimelineStart) + verify(fixture.options.replayController, never()).stop() + + fixture.elapse(2_000) + strategy.captureReplay(false) {} + + val (segment, payload) = capturedSegments(count = 1).single() + assertThat(segment.segmentId).isEqualTo(0) + assertThat(segment.replayStartTimestamp!!.time).isEqualTo(newTimelineStart) + assertThat(payload.filterIsInstance()).isEmpty() + } + + @Test + fun `a segment request made before the jump's frame task ran reads the buffer again in its task`() { + val frames = fixture.storeFrames() + val strategy = fixture.getSut(replayExecutor = fixture.queuedExecutor) + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.runQueuedTasks() + fixture.elapse(3_000) + fixture.jumpWallClock(DAYS.toMillis(1)) + val newTimelineStart = fixture.now + strategy.onScreenshotRecorded(mock()) { frames += it } + fixture.elapse(2_000) + + // the frame from before the jump is still the first one in the cache here + strategy.captureReplay(false) {} + fixture.runQueuedTasks() + + verify(fixture.replayCache) + .createVideoOf(eq(2_000L), eq(newTimelineStart), eq(0), any(), any(), any(), any(), any()) + // not a video of the one frame after the jump, stretched over the day before it + verify(fixture.replayCache, never()) + .createVideoOf( + anyLong(), + eq(segmentStart), + anyInt(), + anyInt(), + anyInt(), + anyInt(), + anyInt(), + any(), + ) + } } diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/ReplayClockTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/ReplayClockTest.kt new file mode 100644 index 00000000000..03db5841da6 --- /dev/null +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/ReplayClockTest.kt @@ -0,0 +1,99 @@ +package io.sentry.android.replay.capture + +import com.google.common.truth.Truth.assertThat +import io.sentry.time.AnchoredClock +import io.sentry.time.EpochClock +import io.sentry.time.TestMonotonicTicker +import io.sentry.time.Timestamp +import java.util.concurrent.TimeUnit.MILLISECONDS +import kotlin.test.Test + +class ReplayClockTest { + private var wallMillis = 1_720_693_523_997L + private val epochClock = EpochClock { Timestamp.ofEpochNanos(MILLISECONDS.toNanos(wallMillis)) } + private val ticker = TestMonotonicTicker() + + private fun elapse(millis: Long) { + wallMillis += millis + ticker.advance(millis, MILLISECONDS) + } + + @Test + fun `follows the wall clock while it does not jump`() { + val clock = ReplayClock(epochClock, ticker) + + elapse(4_321) + + assertThat(clock.nowMillis()).isEqualTo(wallMillis) + assertThat(clock.wallClockJumpMillis()).isEqualTo(0) + } + + @Test + fun `measures time on the ticker when the wall clock jumps`() { + val clock = ReplayClock(epochClock, ticker) + val start = clock.nowMillis() + + elapse(3_000) + wallMillis -= 120_000 + + assertThat(clock.nowMillis()).isEqualTo(start + 3_000) + } + + @Test + fun `ignores a jump within the tolerance`() { + val clock = ReplayClock(epochClock, ticker) + + wallMillis += ReplayClock.JUMP_TOLERANCE_MS + assertThat(clock.wallClockJumpMillis()).isEqualTo(0) + + wallMillis -= 2 * ReplayClock.JUMP_TOLERANCE_MS + assertThat(clock.wallClockJumpMillis()).isEqualTo(0) + } + + @Test + fun `reports a forward jump`() { + val clock = ReplayClock(epochClock, ticker) + + wallMillis += 120_000 + + assertThat(clock.wallClockJumpMillis()).isEqualTo(120_000) + } + + @Test + fun `reports a backward jump`() { + val clock = ReplayClock(epochClock, ticker) + + wallMillis -= ReplayClock.JUMP_TOLERANCE_MS + 1 + + assertThat(clock.wallClockJumpMillis()).isEqualTo(-(ReplayClock.JUMP_TOLERANCE_MS + 1)) + } + + @Test + fun `restart anchors a new timeline on the wall clock`() { + val clock = ReplayClock(epochClock, ticker) + val oldTimeline = clock.timeline + elapse(3_000) + wallMillis -= 120_000 + + val newStart = clock.restart().startTime().epochMillis + + assertThat(newStart).isEqualTo(wallMillis) + assertThat(clock.wallClockJumpMillis()).isEqualTo(0) + elapse(1_000) + assertThat(clock.nowMillis()).isEqualTo(newStart + 1_000) + // the old timeline keeps counting on its own, for what was stamped on it + assertThat(oldTimeline.nowMillis()).isEqualTo(newStart + 120_000 + 1_000) + } + + @Test + fun `continues a timeline it is handed`() { + val timeline = AnchoredClock.create(epochClock, ticker) + elapse(1_000) + wallMillis += 5_000 + + val clock = ReplayClock(epochClock, ticker, timeline) + + assertThat(clock.nowMillis()).isEqualTo(timeline.nowMillis()) + assertThat(clock.wallClockJumpMillis()).isEqualTo(5_000) + } +} diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/SessionCaptureStrategyTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/SessionCaptureStrategyTest.kt index 4c31090cee9..be9cebe69ed 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/SessionCaptureStrategyTest.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/capture/SessionCaptureStrategyTest.kt @@ -1,9 +1,11 @@ package io.sentry.android.replay.capture import android.graphics.Bitmap +import android.view.MotionEvent import com.google.common.truth.Truth.assertThat import io.sentry.Breadcrumb import io.sentry.DateUtils +import io.sentry.Hint import io.sentry.IScopes import io.sentry.Scope import io.sentry.ScopeCallback @@ -35,16 +37,17 @@ import io.sentry.android.replay.maskAllImages import io.sentry.protocol.SdkVersion import io.sentry.protocol.SentryId import io.sentry.rrweb.RRWebBreadcrumbEvent +import io.sentry.rrweb.RRWebEvent +import io.sentry.rrweb.RRWebInteractionEvent +import io.sentry.rrweb.RRWebInteractionEvent.InteractionType import io.sentry.rrweb.RRWebMetaEvent import io.sentry.rrweb.RRWebOptionsEvent import io.sentry.time.TestMonotonicTicker -import io.sentry.transport.CurrentDateProvider import io.sentry.transport.ICurrentDateProvider import java.io.File import java.util.Date import java.util.concurrent.ScheduledExecutorService import java.util.concurrent.TimeUnit.MILLISECONDS -import java.util.concurrent.TimeUnit.SECONDS import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse @@ -57,11 +60,14 @@ import org.mockito.ArgumentMatchers.anyLong import org.mockito.kotlin.any import org.mockito.kotlin.anyOrNull import org.mockito.kotlin.argThat +import org.mockito.kotlin.argumentCaptor import org.mockito.kotlin.check import org.mockito.kotlin.doAnswer import org.mockito.kotlin.eq +import org.mockito.kotlin.inOrder import org.mockito.kotlin.mock import org.mockito.kotlin.never +import org.mockito.kotlin.times import org.mockito.kotlin.verify import org.mockito.kotlin.whenever @@ -121,10 +127,54 @@ class SessionCaptureStrategyTest { bitRate = 20_000, ) + // starts at the real time, so breadcrumbs the scope stamps itself fall into the recording + var now = System.currentTimeMillis() val ticker = TestMonotonicTicker() + /** Time passing: the wall clock and the ticker move together. */ + fun elapse(millis: Long) { + now += millis + ticker.advance(millis, MILLISECONDS) + } + + /** The device clock being changed: only the wall clock moves. */ + fun jumpWallClock(millis: Long) { + now += millis + } + + private val queuedTasks = ArrayDeque() + + /** Runs once in the next submit, before its task is queued, like another thread getting in. */ + var beforeNextSubmit: (() -> Unit)? = null + + /** Holds submitted tasks until [runQueuedTasks], like a busy replay executor. */ + val queuedExecutor = + mock { + doAnswer { + beforeNextSubmit?.also { beforeNextSubmit = null }?.invoke() + queuedTasks += it.arguments[0] as Runnable + null + } + .whenever(mock) + .submit(any()) + } + + fun runQueuedTasks() { + while (queuedTasks.isNotEmpty()) { + queuedTasks.removeFirst().run() + } + } + + fun mockedMotionEvent(action: Int): MotionEvent = mock { + on { actionMasked }.thenReturn(action) + on { getPointerId(anyInt()) }.thenReturn(0) + on { findPointerIndex(anyInt()) }.thenReturn(0) + on { getX(anyInt()) }.thenReturn(1f) + on { getY(anyInt()) }.thenReturn(1f) + } + fun getSut( - dateProvider: ICurrentDateProvider = CurrentDateProvider.getInstance(), + dateProvider: ICurrentDateProvider = ICurrentDateProvider { now }, replayCacheDir: File? = null, replayExecutor: ScheduledExecutorService = mock { doAnswer { invocation -> @@ -150,9 +200,8 @@ class SessionCaptureStrategyTest { .whenever(it) .submit(any()) }, - ) { _ -> - replayCache - } + replayCacheProvider = { _ -> replayCache }, + ) } } @@ -331,7 +380,6 @@ class SessionCaptureStrategyTest { fun `flush uses the timeline after queued segment boundaries`() { val tasks = mutableListOf() val segmentIds = mutableListOf() - val now = System.currentTimeMillis() + fixture.options.sessionReplay.sessionSegmentDuration * 2 val replayExecutor = mock { doAnswer { @@ -347,9 +395,10 @@ class SessionCaptureStrategyTest { } .whenever(fixture.scopes) .captureReplay(any(), any()) - val strategy = fixture.getSut(dateProvider = { now }, replayExecutor = replayExecutor) + val strategy = fixture.getSut(replayExecutor = replayExecutor) strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 2) strategy.onScreenshotRecorded(mock()) {} strategy.flush {} @@ -361,7 +410,6 @@ class SessionCaptureStrategyTest { @Test fun `flush uses request time when executor is delayed`() { val tasks = mutableListOf() - var now = System.currentTimeMillis() + fixture.options.sessionReplay.sessionSegmentDuration val replayExecutor = mock { doAnswer { @@ -371,14 +419,15 @@ class SessionCaptureStrategyTest { .whenever(mock) .submit(any()) } - val strategy = fixture.getSut(dateProvider = { now }, replayExecutor = replayExecutor) + val strategy = fixture.getSut(replayExecutor = replayExecutor) strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) val segmentStart = strategy.segmentTimestamp!!.time - val requestedAt = now + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration) + val requestedAt = fixture.now strategy.flush {} - now += fixture.options.sessionReplay.sessionSegmentDuration + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration) tasks.forEach(Runnable::run) verify(fixture.replayCache) @@ -397,7 +446,7 @@ class SessionCaptureStrategyTest { @Test fun `resume updates the timeline after a queued pause`() { val tasks = mutableListOf() - val now = System.currentTimeMillis() + val now = fixture.now val replayExecutor = mock { doAnswer { @@ -407,7 +456,7 @@ class SessionCaptureStrategyTest { .whenever(mock) .submit(any()) } - val strategy = fixture.getSut(dateProvider = { now }, replayExecutor = replayExecutor) + val strategy = fixture.getSut(replayExecutor = replayExecutor) strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) val segmentStart = Date(now - fixture.options.sessionReplay.sessionSegmentDuration) @@ -434,7 +483,6 @@ class SessionCaptureStrategyTest { @Test fun `executor delay does not trigger a segment boundary`() { val tasks = mutableListOf() - var now = System.currentTimeMillis() val replayExecutor = mock { doAnswer { @@ -444,14 +492,13 @@ class SessionCaptureStrategyTest { .whenever(mock) .submit(any()) } - val strategy = fixture.getSut(dateProvider = { now }, replayExecutor = replayExecutor) + val strategy = fixture.getSut(replayExecutor = replayExecutor) strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) - now += fixture.options.sessionReplay.sessionSegmentDuration - 1 + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration - 1) strategy.onScreenshotRecorded(mock()) {} - now += fixture.options.sessionReplay.sessionDuration - fixture.ticker.advance(fixture.options.sessionReplay.sessionDuration, MILLISECONDS) + fixture.elapse(fixture.options.sessionReplay.sessionDuration) tasks.forEach(Runnable::run) verify(fixture.scopes, never()).captureReplay(any(), any()) @@ -460,10 +507,9 @@ class SessionCaptureStrategyTest { @Test fun `when process is crashing, onScreenshotRecorded does not create new segment`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.captureReplay(true) {} strategy.onScreenshotRecorded(mock()) {} @@ -473,14 +519,13 @@ class SessionCaptureStrategyTest { @Test fun `onScreenshotRecorded creates new segment when segment duration exceeded`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.onScreenshotRecorded(mock()) { frameTimestamp -> - assertEquals(now, frameTimestamp) + assertEquals(fixture.now, frameTimestamp) } var segmentTimestamp: Date? = null @@ -504,12 +549,10 @@ class SessionCaptureStrategyTest { @Test fun `onScreenshotRecorded stops replay when replay duration exceeded`() { - var now = System.currentTimeMillis() - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(mock()) - now += fixture.options.sessionReplay.sessionDuration * 2 - fixture.ticker.advance(fixture.options.sessionReplay.sessionDuration * 2, MILLISECONDS) + fixture.elapse(fixture.options.sessionReplay.sessionDuration * 2) strategy.onScreenshotRecorded(mock()) {} @@ -517,14 +560,32 @@ class SessionCaptureStrategyTest { } @Test - fun `onScreenshotRecorded does not stop replay when the wall clock jumps past the deadline`() { - var now = System.currentTimeMillis() - val strategy = fixture.getSut(dateProvider = { now }) + fun `onScreenshotRecorded stops replay when the wall clock jumps forward past the session duration`() { + val strategy = fixture.getSut() strategy.start() - strategy.onConfigurationChanged(mock()) + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now // the device corrects its clock two hours forwards a second into the recording - now += fixture.options.sessionReplay.sessionDuration * 2 - fixture.ticker.advance(1, SECONDS) + fixture.elapse(1_000) + fixture.jumpWallClock(fixture.options.sessionReplay.sessionDuration * 2) + + var frameTimestamp: Long? = null + strategy.onScreenshotRecorded(mock()) { frameTimestamp = it } + + verify(fixture.options.replayController).stop() + // the recording ends on its own timeline instead of sending a segment hours later + assertThat(frameTimestamp).isEqualTo(segmentStart + 1_000) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(segmentStart) + verify(fixture.scopes, never()).captureReplay(any(), any()) + } + + @Test + fun `onScreenshotRecorded does not stop replay when the wall clock jumps forward less than the session duration`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(1_000) + fixture.jumpWallClock(fixture.options.sessionReplay.sessionDuration - 2_000) strategy.onScreenshotRecorded(mock()) {} @@ -533,13 +594,12 @@ class SessionCaptureStrategyTest { @Test fun `onScreenshotRecorded stops replay when the wall clock steps backwards past the deadline`() { - var now = System.currentTimeMillis() - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(mock()) // an hour of recording, during which the device drags its clock back to before the start fixture.ticker.advance(fixture.options.sessionReplay.sessionDuration, MILLISECONDS) - now -= 1000 + fixture.jumpWallClock(-1000) strategy.onScreenshotRecorded(mock()) {} @@ -583,11 +643,10 @@ class SessionCaptureStrategyTest { @Test fun `fills replay urls from navigation breadcrumbs`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) fixture.scope.addBreadcrumb(Breadcrumb.navigation("from", "to")) @@ -607,11 +666,10 @@ class SessionCaptureStrategyTest { @Test fun `does not throw when navigation destination is not a String`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) fixture.scope.addBreadcrumb(Breadcrumb().apply { category = "navigation" }) @@ -633,11 +691,10 @@ class SessionCaptureStrategyTest { fun `sets screen from scope as replay url`() { fixture.scope.screen = "MainActivity" - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.onScreenshotRecorded(mock()) {} @@ -674,11 +731,10 @@ class SessionCaptureStrategyTest { fixture.options.sessionReplay.quality = HIGH fixture.options.sessionReplay.addMaskViewClass("my.custom.View") - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.onScreenshotRecorded(mock()) {} @@ -714,11 +770,10 @@ class SessionCaptureStrategyTest { @Test fun `does not record replay options event for segment above 0`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.onScreenshotRecorded(mock()) {} verify(fixture.scopes) @@ -737,11 +792,10 @@ class SessionCaptureStrategyTest { @Test fun `registerTraceId includes trace IDs in next segment`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) val traceId1 = SentryId() val traceId2 = SentryId() @@ -764,11 +818,10 @@ class SessionCaptureStrategyTest { @Test fun `registerTraceId clears trace IDs after segment is created`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) val traceId = SentryId() strategy.registerTraceId(traceId) @@ -797,11 +850,10 @@ class SessionCaptureStrategyTest { @Test fun `registerTraceId ignores empty trace ID`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.registerTraceId(SentryId.EMPTY_ID) @@ -816,11 +868,10 @@ class SessionCaptureStrategyTest { @Test fun `registerSegmentName includes unique segment names in next segment and clears them`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.registerSegmentName("CheckoutActivity") strategy.registerSegmentName("CheckoutActivity") @@ -850,11 +901,10 @@ class SessionCaptureStrategyTest { @Test fun `registerSegmentName ignores empty names and limits names to 100`() { - val now = - System.currentTimeMillis() + (fixture.options.sessionReplay.sessionSegmentDuration * 5) - val strategy = fixture.getSut(dateProvider = { now }) + val strategy = fixture.getSut() strategy.start() strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 5) strategy.registerSegmentName("") repeat(101) { strategy.registerSegmentName("ProductActivity$it") } @@ -867,4 +917,277 @@ class SessionCaptureStrategyTest { any(), ) } + + private fun SessionCaptureStrategy.recordFrame() = + onScreenshotRecorded(mock()) { addFrame(File("$it.jpg"), it) } + + /** Matches the [ReplayCache.createVideoOf] call that encodes one segment. */ + private fun ReplayCache.encodedVideoOf(duration: Long, from: Long, segmentId: Int) = + createVideoOf(eq(duration), eq(from), eq(segmentId), any(), any(), any(), any(), any()) + + /** The recording payload of every captured segment, by segment id. */ + private fun capturedPayloads(count: Int): Map> { + val events = argumentCaptor() + val hints = argumentCaptor() + verify(fixture.scopes, times(count)).captureReplay(events.capture(), hints.capture()) + return events.allValues.zip(hints.allValues).associate { (event, hint) -> + event.segmentId to hint.replayRecording!!.payload!! + } + } + + @Test + fun `without a wall-clock jump, frames and segments are stamped with the wall clock`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(segmentStart) + + fixture.elapse(1_000) + strategy.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(fixture.now) } + fixture.elapse(4_000) + strategy.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(fixture.now) } + verify(fixture.replayCache).encodedVideoOf(5_000, segmentStart, 0) + + fixture.elapse(2_000) + strategy.flush {} + val nextSegmentStart = segmentStart + Fixture.VIDEO_DURATION + verify(fixture.replayCache).encodedVideoOf(fixture.now - nextSegmentStart, nextSegmentStart, 1) + } + + @Test + fun `a wall-clock jump within the tolerance is not followed`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.elapse(1_000) + fixture.jumpWallClock(ReplayClock.JUMP_TOLERANCE_MS) + + strategy.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(segmentStart + 1_000) } + + verify(fixture.scopes, never()).captureReplay(any(), any()) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(segmentStart) + } + + @Test + fun `a backward wall-clock jump closes the segment where the old timeline ended`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.elapse(1_000) + strategy.recordFrame() + fixture.elapse(2_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + + strategy.recordFrame() + + inOrder(fixture.replayCache) { + verify(fixture.replayCache).addFrame(any(), eq(segmentStart + 1_000), anyOrNull()) + verify(fixture.replayCache).encodedVideoOf(3_000, segmentStart, 0) + verify(fixture.replayCache).rotate(eq(segmentStart + 3_000)) + // stored only once the old timeline is closed, so it is not encoded or rotated with it + verify(fixture.replayCache).addFrame(any(), eq(newTimelineStart), anyOrNull()) + } + verify(fixture.scopes).captureReplay(argThat { segmentId == 0 }, any()) + assertThat(strategy.currentSegment).isEqualTo(1) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(newTimelineStart) + // what crash recovery on the next launch starts the recovered segment at + assertThat(fixture.persistedSegment[SEGMENT_KEY_TIMESTAMP]) + .isEqualTo(DateUtils.getTimestamp(Date(newTimelineStart))) + + repeat(4) { + fixture.elapse(1_000) + strategy.recordFrame() + } + verify(fixture.scopes, times(1)).captureReplay(any(), any()) + + fixture.elapse(1_000) + strategy.recordFrame() + verify(fixture.replayCache).encodedVideoOf(5_000, newTimelineStart, 1) + verify(fixture.scopes, times(2)).captureReplay(any(), any()) + } + + @Test + fun `a forward wall-clock jump closes the segment instead of cutting frozen ones`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.elapse(3_000) + fixture.jumpWallClock(120_000) + val newTimelineStart = fixture.now + + strategy.recordFrame() + repeat(4) { + fixture.elapse(1_000) + strategy.recordFrame() + } + + verify(fixture.replayCache).encodedVideoOf(3_000, segmentStart, 0) + verify(fixture.scopes, times(1)).captureReplay(any(), any()) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(newTimelineStart) + + fixture.elapse(1_000) + strategy.recordFrame() + verify(fixture.replayCache).encodedVideoOf(5_000, newTimelineStart, 1) + verify(fixture.scopes, times(2)).captureReplay(any(), any()) + } + + @Test + fun `breadcrumbs stamped after a wall-clock jump go into the segment after it`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.scope.addBreadcrumb( + Breadcrumb(Date(segmentStart + 500)).apply { + category = "test" + message = "before" + } + ) + fixture.elapse(3_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + strategy.recordFrame() + + fixture.scope.addBreadcrumb( + Breadcrumb(Date(newTimelineStart + 500)).apply { + category = "test" + message = "after" + } + ) + fixture.elapse(5_000) + strategy.recordFrame() + + val payloads = capturedPayloads(count = 2) + assertThat(payloads[0]!!.filterIsInstance().map { it.message }) + .containsExactly("before") + assertThat(payloads[1]!!.filterIsInstance().map { it.message }) + .containsExactly("after") + } + + @Test + fun `touch events stay with the timeline they were stamped on`() { + val strategy = fixture.getSut(replayExecutor = fixture.queuedExecutor) + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.runQueuedTasks() + val segmentStart = fixture.now + fixture.elapse(1_000) + strategy.onTouchEvent(fixture.mockedMotionEvent(MotionEvent.ACTION_DOWN)) + fixture.elapse(2_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + + strategy.recordFrame() + // stamped on the new timeline while the old one is still being closed + fixture.elapse(100) + strategy.onTouchEvent(fixture.mockedMotionEvent(MotionEvent.ACTION_UP)) + fixture.runQueuedTasks() + fixture.elapse(4_900) + strategy.recordFrame() + fixture.runQueuedTasks() + + val payloads = capturedPayloads(count = 2) + assertThat(payloads[0]!!.filterIsInstance().map { it.timestamp }) + .containsExactly(segmentStart + 1_000) + val touchesAfterJump = payloads[1]!!.filterIsInstance() + assertThat(touchesAfterJump.map { it.interactionType }) + .containsExactly(InteractionType.TouchEnd) + assertThat(touchesAfterJump.map { it.timestamp }).containsExactly(newTimelineStart + 100) + } + + @Test + fun `executor delay across a wall-clock jump keeps both timelines apart`() { + val strategy = fixture.getSut(replayExecutor = fixture.queuedExecutor) + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.runQueuedTasks() + val segmentStart = fixture.now + fixture.elapse(1_000) + strategy.recordFrame() + fixture.elapse(2_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + strategy.recordFrame() + + fixture.elapse(fixture.options.sessionReplay.sessionSegmentDuration * 2) + fixture.runQueuedTasks() + + inOrder(fixture.replayCache) { + verify(fixture.replayCache).addFrame(any(), eq(segmentStart + 1_000), anyOrNull()) + verify(fixture.replayCache).encodedVideoOf(3_000, segmentStart, 0) + verify(fixture.replayCache).addFrame(any(), eq(newTimelineStart), anyOrNull()) + } + verify(fixture.scopes, times(1)).captureReplay(any(), any()) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(newTimelineStart) + } + + @Test + fun `flush queued after a wall-clock jump cuts from the new timeline`() { + val strategy = fixture.getSut(replayExecutor = fixture.queuedExecutor) + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.runQueuedTasks() + val segmentStart = fixture.now + fixture.elapse(3_000) + fixture.jumpWallClock(120_000) + val newTimelineStart = fixture.now + strategy.recordFrame() + fixture.elapse(2_000) + + strategy.flush {} + fixture.runQueuedTasks() + + verify(fixture.replayCache).encodedVideoOf(3_000, segmentStart, 0) + verify(fixture.replayCache).encodedVideoOf(2_000, newTimelineStart, 1) + } + + @Test + fun `the first frame after resume follows a wall-clock jump while paused`() { + val strategy = fixture.getSut() + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + val segmentStart = fixture.now + fixture.elapse(2_000) + strategy.pause() + fixture.elapse(10_000) + fixture.jumpWallClock(-120_000) + + strategy.resume() + val resumedAt = strategy.segmentTimestamp!!.time + fixture.elapse(1_000) + strategy.onScreenshotRecorded(mock()) { assertThat(it).isEqualTo(fixture.now) } + + assertThat(resumedAt).isEqualTo(segmentStart + 12_000) + // closes what the old timeline recorded since resuming, which is nothing in a real cache + verify(fixture.replayCache).encodedVideoOf(1_000, resumedAt, 1) + assertThat(strategy.segmentTimestamp!!.time).isEqualTo(fixture.now) + } + + @Test + fun `a segment request queued behind a wall-clock jump it read the clock before uses the new timeline`() { + val strategy = fixture.getSut(replayExecutor = fixture.queuedExecutor) + strategy.start() + strategy.onConfigurationChanged(fixture.recorderConfig) + fixture.runQueuedTasks() + val segmentStart = fixture.now + fixture.elapse(3_000) + fixture.jumpWallClock(-120_000) + val newTimelineStart = fixture.now + // the flush reads the clock on the old timeline, then a frame follows the jump and queues its + // task first + fixture.beforeNextSubmit = { strategy.recordFrame() } + + strategy.flush {} + fixture.elapse(500) + fixture.runQueuedTasks() + + verify(fixture.replayCache).encodedVideoOf(3_000, segmentStart, 0) + // not the 2 minutes from the new timeline's start to the request time on the old one + verify(fixture.replayCache).encodedVideoOf(500, newTimelineStart, 1) + } }