diff --git a/CHANGELOG.md b/CHANGELOG.md index d05335e9aa..68852ffb81 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,8 @@ - Prevent concurrent PixelCopy access during Session Replay masking and bitmap cleanup ([#5808](https://github.com/getsentry/sentry-java/pull/5808)) - Release `MediaMuxer` when the replay video encoder fails to start to avoid a resource leak ([#5607](https://github.com/getsentry/sentry-java/pull/5607)) - Set the correct platform (`android` instead of `java`) on ANR profile chunks so they are billed as UI Profile Hours rather than Continuous Profile Hours ([#5836](https://github.com/getsentry/sentry-java/pull/5836)) +- Prevent an ANR when the Session Replay video encoder gets stuck ([#5842](https://github.com/getsentry/sentry-java/pull/5842)) + - Some hardware encoders never signal end-of-stream, which made the replay worker spin forever while holding the encoder lock. The app's lifecycle callbacks then blocked on that lock and the app froze until the system killed it. The encoder now gives up instead of spinning, and closing the replay cache no longer waits indefinitely for a wedged encoder. ### Performance diff --git a/sentry-android-replay/build.gradle.kts b/sentry-android-replay/build.gradle.kts index 45838cb1e1..6d03ba771b 100644 --- a/sentry-android-replay/build.gradle.kts +++ b/sentry-android-replay/build.gradle.kts @@ -83,6 +83,7 @@ dependencies { testImplementation(libs.androidx.test.ext.junit) testImplementation(libs.androidx.test.runner) testImplementation(libs.awaitility.kotlin) + testImplementation(libs.google.truth) testImplementation(libs.mockito.kotlin) testImplementation(libs.mockito.inline) testImplementation(libs.androidx.compose.ui) diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/ReplayCache.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/ReplayCache.kt index 55891fea1a..3c538028ea 100644 --- a/sentry-android-replay/src/main/java/io/sentry/android/replay/ReplayCache.kt +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/ReplayCache.kt @@ -22,6 +22,7 @@ import java.io.File import java.io.StringReader import java.util.Date import java.util.LinkedList +import java.util.concurrent.TimeUnit.MILLISECONDS import java.util.concurrent.atomic.AtomicBoolean /** @@ -280,10 +281,27 @@ public class ReplayCache(private val options: SentryOptions, private val replayI } override fun close() { - encoderLock.acquire().use { - encoder?.release() - encoder = null + // close() is called inline from the lifecycle path (ReplayIntegration.stop/close), which holds + // its own lock, so blocking here can freeze the main thread. If the encoder is wedged in a + // native MediaCodec call we'd never get the lock, so we give up instead: the already-dead codec + // is not released (leaking a native handle), which beats an ANR. + try { + val token = encoderLock.tryAcquire(ENCODER_RELEASE_TIMEOUT_MS, MILLISECONDS) + if (token == null) { + options.logger.log( + WARNING, + "Timed out waiting for the video encoder, skipping its release to not block the caller", + ) + } else { + token.use { + encoder?.release() + encoder = null + } + } + } catch (e: InterruptedException) { + Thread.currentThread().interrupt() } + // has to happen on all paths, callers rely on it to stop persisting segment values isClosed.set(true) } @@ -314,6 +332,13 @@ public class ReplayCache(private val options: SentryOptions, private val replayI } internal companion object { + /** + * How long [close] waits for the video encoder to become available. Below Android's ~5s ANR + * budget, and above the encoder's own bail-out (see MAX_EOS_STALL_ITERATIONS), so an encoder + * that's merely slow is still awaited rather than abandoned. + */ + private const val ENCODER_RELEASE_TIMEOUT_MS = 2000L + internal const val ONGOING_SEGMENT = ".ongoing_segment" internal const val SEGMENT_KEY_HEIGHT = "config.height" diff --git a/sentry-android-replay/src/main/java/io/sentry/android/replay/video/SimpleVideoEncoder.kt b/sentry-android-replay/src/main/java/io/sentry/android/replay/video/SimpleVideoEncoder.kt index d0cafd9f1a..68aacf2f15 100644 --- a/sentry-android-replay/src/main/java/io/sentry/android/replay/video/SimpleVideoEncoder.kt +++ b/sentry-android-replay/src/main/java/io/sentry/android/replay/video/SimpleVideoEncoder.kt @@ -45,6 +45,16 @@ import kotlin.LazyThreadSafetyMode.NONE private const val TIMEOUT_USEC = 100_000L +/** + * How many consecutive [MediaCodec.dequeueOutputBuffer] calls may come back without producing + * anything before we give up on the encoder. At [TIMEOUT_USEC] per call that's ~1s. + * + * Some hardware encoders never emit [MediaCodec.BUFFER_FLAG_END_OF_STREAM] after + * [MediaCodec.signalEndOfInputStream], which used to spin the drain loop forever while holding the + * encoder lock, wedging the whole replay pipeline (and with it the app's lifecycle callbacks). + */ +private const val MAX_EOS_STALL_ITERATIONS = 10 + @SuppressLint("UseRequiresApi") @TargetApi(26) internal class SimpleVideoEncoder( @@ -214,19 +224,26 @@ internal class SimpleVideoEncoder( mediaCodec.signalEndOfInputStream() } var encoderOutputBuffers: Array? = mediaCodec.outputBuffers + // counts consecutive iterations that made no progress, so a codec that never signals EOS can't + // spin us forever, see MAX_EOS_STALL_ITERATIONS + var stalledIterations = 0 while (true) { val encoderStatus: Int = mediaCodec.dequeueOutputBuffer(bufferInfo, TIMEOUT_USEC) if (encoderStatus == MediaCodec.INFO_TRY_AGAIN_LATER) { // no output available yet if (!endOfStream) { break // out of while - } else if (options.sessionReplay.isDebug) { + } + stalledIterations++ + if (options.sessionReplay.isDebug) { options.logger.log(DEBUG, "[Encoder]: no output available, spinning to await EOS") } } else if (encoderStatus == MediaCodec.INFO_OUTPUT_BUFFERS_CHANGED) { + stalledIterations = 0 // not expected for an encoder encoderOutputBuffers = mediaCodec.outputBuffers } else if (encoderStatus == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED) { + stalledIterations = 0 // should happen before receiving buffers, and should only happen once if (frameMuxer.isStarted()) { throw RuntimeException("format changed twice") @@ -245,8 +262,10 @@ internal class SimpleVideoEncoder( "[Encoder]: unexpected result from encoder.dequeueOutputBuffer: $encoderStatus", ) } - // let's ignore it + // let's ignore it, but still count it as no progress so we can't loop on it forever + stalledIterations++ } else { + stalledIterations = 0 val encodedData = encoderOutputBuffers?.get(encoderStatus) ?: throw RuntimeException("encoderOutputBuffer $encoderStatus was null") @@ -279,6 +298,14 @@ internal class SimpleVideoEncoder( break // out of while } } + + if (stalledIterations >= MAX_EOS_STALL_ITERATIONS) { + options.logger.log( + DEBUG, + "[Encoder]: encoder made no progress for $stalledIterations iterations, dropping the remaining frames", + ) + break // out of while + } } } diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayCacheTest.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayCacheTest.kt index 23e8d60044..38ac5474c5 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayCacheTest.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/ReplayCacheTest.kt @@ -4,6 +4,8 @@ import android.graphics.Bitmap import android.graphics.Bitmap.CompressFormat.JPEG import android.graphics.Bitmap.Config.ARGB_8888 import androidx.test.ext.junit.runners.AndroidJUnit4 +import com.google.common.truth.Truth.assertThat +import com.google.common.truth.Truth.assertWithMessage import io.sentry.DateUtils import io.sentry.SentryOptions import io.sentry.SentryReplayEvent.ReplayType @@ -24,7 +26,9 @@ import io.sentry.rrweb.RRWebInteractionEvent.InteractionType.TouchEnd import io.sentry.rrweb.RRWebInteractionEvent.InteractionType.TouchStart import java.io.File import java.util.concurrent.CountDownLatch +import java.util.concurrent.TimeUnit.SECONDS import java.util.concurrent.atomic.AtomicReference +import kotlin.concurrent.thread import kotlin.test.BeforeTest import kotlin.test.Test import kotlin.test.assertEquals @@ -59,6 +63,9 @@ class ReplayCacheTest { fun `set up`() { ReplayShadowMediaCodec.framesToEncode = 5 ReplayShadowMediaCodec.throwOnStart = false + ReplayShadowMediaCodec.neverSignalEos = false + ReplayShadowMediaCodec.blockOnDequeue = null + ReplayShadowMediaCodec.blockedOnDequeue = CountDownLatch(1) ShadowBitmapFactory.setAllowInvalidImageData(true) } @@ -654,4 +661,68 @@ class ReplayCacheTest { // No crash is success assertNull(error.get()) } + + @Test + fun `createVideoOf returns when the encoder never signals end of stream`() { + ReplayShadowMediaCodec.neverSignalEos = true + val replayCache = fixture.getSut(tmpDir) + + val bitmap = Bitmap.createBitmap(1, 1, ARGB_8888) + replayCache.addFrame(bitmap, 1) + + val done = CountDownLatch(1) + val error = AtomicReference() + val encoder = + thread(isDaemon = true) { + try { + replayCache.createVideoOf(1000L, 0L, 0, 100, 200, 1, 20_000) + } catch (t: Throwable) { + error.set(t) + } finally { + done.countDown() + } + } + + assertWithMessage("createVideoOf did not return, the drain loop is spinning") + .that(done.await(30, SECONDS)) + .isTrue() + encoder.join(SECONDS.toMillis(10)) + assertThat(error.get()).isNull() + } + + @Test + fun `close does not block when the encoder is wedged, and still marks the cache closed`() { + val wedge = CountDownLatch(1) + ReplayShadowMediaCodec.blockOnDequeue = wedge + val replayCache = fixture.getSut(tmpDir) + + val bitmap = Bitmap.createBitmap(1, 1, ARGB_8888) + replayCache.addFrame(bitmap, 1) + + // parks inside MediaCodec while holding the encoder lock + val encoder = + thread(isDaemon = true) { replayCache.createVideoOf(1000L, 0L, 0, 100, 200, 1, 20_000) } + try { + assertWithMessage("the encoder never reached dequeueOutputBuffer") + .that(ReplayShadowMediaCodec.blockedOnDequeue.await(30, SECONDS)) + .isTrue() + + // on a separate thread so a regression fails the test instead of hanging the run + val closed = CountDownLatch(1) + thread(isDaemon = true) { + replayCache.close() + closed.countDown() + } + assertWithMessage("close() blocked on the wedged encoder") + .that(closed.await(30, SECONDS)) + .isTrue() + + // giving up on the lock still counts as closed, otherwise we'd keep persisting segments + replayCache.persistSegmentValues(SEGMENT_KEY_ID, "0") + assertThat(File(replayCache.replayCacheDir, ONGOING_SEGMENT).exists()).isFalse() + } finally { + wedge.countDown() + encoder.join(SECONDS.toMillis(10)) + } + } } diff --git a/sentry-android-replay/src/test/java/io/sentry/android/replay/util/ReplayShadowMediaCodec.kt b/sentry-android-replay/src/test/java/io/sentry/android/replay/util/ReplayShadowMediaCodec.kt index 60ccb15774..391f2b3baa 100644 --- a/sentry-android-replay/src/test/java/io/sentry/android/replay/util/ReplayShadowMediaCodec.kt +++ b/sentry-android-replay/src/test/java/io/sentry/android/replay/util/ReplayShadowMediaCodec.kt @@ -3,6 +3,7 @@ package io.sentry.android.replay.util import android.media.MediaCodec import android.media.MediaCodec.BufferInfo import java.nio.ByteBuffer +import java.util.concurrent.CountDownLatch import java.util.concurrent.TimeUnit.MICROSECONDS import java.util.concurrent.TimeUnit.MILLISECONDS import java.util.concurrent.atomic.AtomicBoolean @@ -16,6 +17,18 @@ class ReplayShadowMediaCodec : ShadowMediaCodec() { var frameRate = 1 var framesToEncode = 5 var throwOnStart = false + + /** Simulates an encoder that never emits [MediaCodec.BUFFER_FLAG_END_OF_STREAM]. */ + var neverSignalEos = false + + /** + * When set, [dequeueOutputBuffer] awaits this latch, simulating a native call that never + * returns. [blockedOnDequeue] is counted down right before, so tests can wait until the codec + * is actually stuck. + */ + var blockOnDequeue: CountDownLatch? = null + + var blockedOnDequeue = CountDownLatch(1) } private val encoded = AtomicBoolean(false) @@ -30,6 +43,9 @@ class ReplayShadowMediaCodec : ShadowMediaCodec() { @Implementation fun signalEndOfInputStream() { + if (neverSignalEos) { + return + } encodeFrame(framesToEncode, frameRate, 0, MediaCodec.BUFFER_FLAG_END_OF_STREAM) } @@ -37,6 +53,10 @@ class ReplayShadowMediaCodec : ShadowMediaCodec() { @Implementation fun dequeueOutputBuffer(info: BufferInfo, timeoutUs: Long): Int { + blockOnDequeue?.let { + blockedOnDequeue.countDown() + it.await() + } val encoderStatus = super.native_dequeueOutputBuffer(info, timeoutUs) super.validateOutputByteBuffer(getOutputBuffers(), encoderStatus, info) if (encoderStatus == MediaCodec.INFO_TRY_AGAIN_LATER && !encoded.getAndSet(true)) { diff --git a/sentry/api/sentry.api b/sentry/api/sentry.api index 7e258b0d4b..0bfc195c7b 100644 --- a/sentry/api/sentry.api +++ b/sentry/api/sentry.api @@ -7634,6 +7634,7 @@ public final class io/sentry/util/AutoClosableReentrantLock : io/sentry/ISentryL public fun ()V public fun acquire ()Lio/sentry/ISentryLifecycleToken; public fun close ()V + public fun tryAcquire (JLjava/util/concurrent/TimeUnit;)Lio/sentry/ISentryLifecycleToken; } public final class io/sentry/util/CheckInUtils { diff --git a/sentry/src/main/java/io/sentry/util/AutoClosableReentrantLock.java b/sentry/src/main/java/io/sentry/util/AutoClosableReentrantLock.java index cf53d860e0..617c1a5b4f 100644 --- a/sentry/src/main/java/io/sentry/util/AutoClosableReentrantLock.java +++ b/sentry/src/main/java/io/sentry/util/AutoClosableReentrantLock.java @@ -1,6 +1,7 @@ package io.sentry.util; import io.sentry.ISentryLifecycleToken; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReferenceFieldUpdater; import java.util.concurrent.locks.ReentrantLock; import org.jetbrains.annotations.ApiStatus; @@ -38,6 +39,19 @@ public final class AutoClosableReentrantLock implements ISentryLifecycleToken { return this; } + /** + * Like {@link #acquire()}, but gives up after {@code timeout}. Use it when blocking forever would + * be worse than not doing the work at all, e.g. on a path that can run on the main thread. + * + * @return the token (this instance) if the lock was acquired, or {@code null} if it wasn't. A + * {@code null} return means the lock is not held, so {@link #close()} must not be + * called for it. + */ + public @Nullable ISentryLifecycleToken tryAcquire( + final long timeout, final @NotNull TimeUnit unit) throws InterruptedException { + return getOrCreateLock().tryLock(timeout, unit) ? this : null; + } + @Override public void close() { Objects.requireNonNull(lock, "close() called before acquire()").unlock(); diff --git a/sentry/src/test/java/io/sentry/util/AutoClosableReentrantLockTest.kt b/sentry/src/test/java/io/sentry/util/AutoClosableReentrantLockTest.kt index 943a2c2bf7..b46cfbaea5 100644 --- a/sentry/src/test/java/io/sentry/util/AutoClosableReentrantLockTest.kt +++ b/sentry/src/test/java/io/sentry/util/AutoClosableReentrantLockTest.kt @@ -1,5 +1,6 @@ package io.sentry.util +import com.google.common.truth.Truth.assertThat import java.util.concurrent.CountDownLatch import java.util.concurrent.TimeUnit import java.util.concurrent.atomic.AtomicInteger @@ -41,6 +42,55 @@ class AutoClosableReentrantLockTest { assertFalse(lock.isLocked) } + @Test + fun `tryAcquire returns the lock itself as the token when free`() { + val lock = AutoClosableReentrantLock() + val token = lock.tryAcquire(1, TimeUnit.SECONDS) + assertThat(token).isSameInstanceAs(lock) + token!!.use { assertThat(lock.isLocked).isTrue() } + assertThat(lock.isLocked).isFalse() + } + + @Test + fun `tryAcquire does not allocate the underlying lock until first use`() { + val lock = AutoClosableReentrantLock() + assertThat(lock.isLockAllocated).isFalse() + lock.tryAcquire(1, TimeUnit.SECONDS)!!.use {} + assertThat(lock.isLockAllocated).isTrue() + } + + @Test + fun `tryAcquire returns null when another thread holds the lock past the timeout`() { + val lock = AutoClosableReentrantLock() + val acquired = CountDownLatch(1) + val release = CountDownLatch(1) + val holder = Thread { + lock.acquire().use { + acquired.countDown() + release.await() + } + } + holder.start() + try { + assertThat(acquired.await(10, TimeUnit.SECONDS)).isTrue() + assertThat(lock.tryAcquire(10, TimeUnit.MILLISECONDS)).isNull() + } finally { + release.countDown() + holder.join(TimeUnit.SECONDS.toMillis(10)) + } + assertThat(lock.isLocked).isFalse() + } + + @Test + fun `tryAcquire is reentrant from the same thread`() { + val lock = AutoClosableReentrantLock() + lock.acquire().use { + lock.tryAcquire(0, TimeUnit.MILLISECONDS)!!.use { assertThat(lock.isLocked).isTrue() } + assertThat(lock.isLocked).isTrue() + } + assertThat(lock.isLocked).isFalse() + } + @Test fun `mutually excludes concurrent threads`() { val lock = AutoClosableReentrantLock()