-
-
Notifications
You must be signed in to change notification settings - Fork 476
fix(replay): Don't let a wedged video encoder freeze the app #5842
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
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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 | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. m: Thoughts about lifting this decision to the call site? That'd let us reduce how much we peg ReplayCache's implementation to its current caller. Eg, we could:
Long-term side note: If we had a general pattern where, say, the Integration owned the execution context / threading decisions, we could leave everything beneath it thread _un_safe on the assumption that our Integrations would serialize execution via thread confinement by default. That'd make the bulk of our integration code much easier to implement and reason about. I haven't looked in detail, but seems like that sort of pattern should be possible, given the very task-oriented nature of our processing + the fact that the host app needs very little from the SDK in real-time. |
||
| // 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, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. ok so just to check my understanding, we try to get the lock only to make sure nobody else is holding it before calling |
||
| "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() | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. do we need to surround this with |
||
| } | ||
| // 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" | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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 | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. how did we determine |
||
|
|
||
| @SuppressLint("UseRequiresApi") | ||
| @TargetApi(26) | ||
| internal class SimpleVideoEncoder( | ||
|
|
@@ -214,19 +224,26 @@ internal class SimpleVideoEncoder( | |
| mediaCodec.signalEndOfInputStream() | ||
| } | ||
| var encoderOutputBuffers: Array<ByteBuffer?>? = 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 | ||
| } | ||
| } | ||
| } | ||
|
|
||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -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<Throwable?>() | ||
| 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)) | ||
| } | ||
| } | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. l: Consider adding tests showing that the encoder is or isn't invoked depending on whether lock acquisition times out in ReplayCache.close(). |
||
| } | ||
Uh oh!
There was an error while loading. Please reload this page.