diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/GetVideoController.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/GetVideoController.kt index f1fce2f1f9..79478bdc34 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/GetVideoController.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/GetVideoController.kt @@ -81,6 +81,16 @@ fun GetVideoController( ).onEach { state -> Log.d("PlaybackService") { "Controller instance: ${state.controller}" } + // A warm-pool ExoPlayer can be handed back still carrying a prior + // PlaybackException (e.g. a decoder-init failure from an earlier acquire). The + // re-prepare below clears it before WatchPlaybackErrors ever attaches, so this + // is the only place the stale error — and its decoder/codec cause chain — is + // observable. Logged so a "Can't play this video" blink that self-heals can be + // attributed to warm-pool reuse rather than a genuinely undecodable stream. + state.controller.playerError?.let { err -> + Log.w(ERROR_LOG_TAG) { "Controller arrived carrying error for ${mediaItem.item.mediaId}: ${err.describe()}" } + } + // The default ExoPlayer volume is 1f and the MediaSessionPool reset lambda // sets it to 0f when the player is acquired, so the controller arrives at 0f. // Read first and only push an IPC if the value actually needs to change — @@ -110,6 +120,11 @@ fun GetVideoController( val targetMediaId = mediaItem.item.mediaId val needsLoad = state.controller.currentMediaItem?.mediaId != targetMediaId if (needsLoad) { + // Cold load: a fresh decoder/codec instance gets allocated here. If a + // second controller for the same URI is still alive (see liveControllers + // in PlaybackServiceClient), this prepare() is where MediaCodec.start() + // can collide and fail. + Log.d("PlaybackService") { "Cold load (setMediaItem+prepare) for $targetMediaId" } state.controller.setMediaItem(mediaItem.item) state.controller.prepare() } else if (state.controller.playbackState == Player.STATE_IDLE) { diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/VideoView.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/VideoView.kt index 5df1c13240..45f72cf3fe 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/VideoView.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/VideoView.kt @@ -193,7 +193,12 @@ fun VideoView( DisplayBlurHash( blurhash, null, - contentScale, + // The placeholder bitmap is decoded at the blurhash's DCT component-grid aspect + // (e.g. a 5x5 grid -> a square bitmap), NOT the real media shape. When `ratio` is + // known the Box is already sized to the true aspect, so crop the placeholder to + // fill it. Without this, FillWidth letterboxes the square placeholder inside the + // taller portrait box — the "square blurhash on a twice-as-tall space" bug. + if (ratio != null) ContentScale.Crop else contentScale, if (ratio != null) borderModifier.aspectRatio(ratio) else borderModifier, thumbhash = thumbhash, ) diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/WatchPlaybackErrors.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/WatchPlaybackErrors.kt index 6a8e6d7467..8141b4a80f 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/WatchPlaybackErrors.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/composable/WatchPlaybackErrors.kt @@ -30,8 +30,33 @@ import androidx.media3.common.MediaItem import androidx.media3.common.PlaybackException import androidx.media3.common.Player import androidx.media3.common.util.UnstableApi +import com.vitorpamplona.quartz.utils.Log import kotlinx.coroutines.delay +// Debug tag for the playback-error lifecycle. Logs every appearance, clear, synthetic-stall raise +// and recovery so a transient decoder-init collision (which self-recovers on a later attempt) can +// be told apart from a genuinely undecodable stream in a field logcat. See WatchPlaybackErrors. +internal const val ERROR_LOG_TAG = "PlaybackError" + +/** + * Flattens a [PlaybackException] into a single line: error code, message, and the full nested + * cause chain (e.g. `DecoderInitializationException <- MediaCodec.CodecException`). The cause + * chain is what distinguishes "format truly unsupported" from "decoder failed to start while a + * second controller held the codec" — both surface as the same top-level renderer error with + * `format_supported=YES`. + * + * Internal (not private) so [GetVideoController] can log the same detail at controller-acquire + * time — a warm-pool player can arrive already in ERROR and get re-prepared (cleared) before + * this watcher ever attaches, so the acquire site is the only place that error is observable. + */ +internal fun PlaybackException.describe(): String { + val causeChain = + generateSequence(cause) { it.cause } + .joinToString(" <- ") { "${it::class.simpleName}: ${it.message}" } + .ifEmpty { "none" } + return "code=$errorCodeName($errorCode) msg=$message causes=[$causeChain]" +} + // How often the decode-stall watchdog samples the controller's position/buffer. private const val STALL_POLL_INTERVAL_MS = 1_000L @@ -69,10 +94,18 @@ fun WatchPlaybackErrors(controllerState: MediaControllerState) { // Prime from the controller's current state — a warm-pool player may already be in ERROR // when we attach, in which case onPlayerErrorChanged will not fire again until prepare(). errorState.value = controller.playerError + controller.playerError?.let { + Log.w(ERROR_LOG_TAG) { "Primed with existing error on ${controller.currentMediaItem?.mediaId}: ${it.describe()}" } + } val listener = object : Player.Listener { override fun onPlayerErrorChanged(error: PlaybackException?) { + if (error != null) { + Log.w(ERROR_LOG_TAG) { "Error raised on ${controller.currentMediaItem?.mediaId}: ${error.describe()}" } + } else if (errorState.value != null) { + Log.d(ERROR_LOG_TAG) { "Error cleared on ${controller.currentMediaItem?.mediaId}" } + } errorState.value = error } @@ -81,7 +114,10 @@ fun WatchPlaybackErrors(controllerState: MediaControllerState) { reason: Int, ) { // A new item on a pooled player starts fresh; drop any error from the old one. - if (errorState.value != null) errorState.value = null + if (errorState.value != null) { + Log.d(ERROR_LOG_TAG) { "Error dropped on media transition (reason=$reason) -> ${mediaItem?.mediaId}" } + errorState.value = null + } } override fun onPlaybackStateChanged(state: Int) { @@ -90,7 +126,10 @@ fun WatchPlaybackErrors(controllerState: MediaControllerState) { // STATE_BUFFERING: the synthetic decode-stall error below is raised *while* // buffering, and clearing on every buffering event would wipe it instantly. if (state == Player.STATE_READY) { - if (errorState.value != null) errorState.value = null + if (errorState.value != null) { + Log.d(ERROR_LOG_TAG) { "Recovered (STATE_READY) on ${controller.currentMediaItem?.mediaId} — clearing overlay" } + errorState.value = null + } } } } @@ -141,6 +180,10 @@ private suspend fun watchForDecodeStall( if (unproductiveSinceMs < 0) { unproductiveSinceMs = now } else if (now - unproductiveSinceMs >= STALL_TIMEOUT_MS && errorState.value == null) { + Log.w(ERROR_LOG_TAG) { + "Synthetic decode-stall after ${STALL_TIMEOUT_MS}ms fed-but-frozen " + + "(pos=$position buffered=${controller.bufferedPosition}) on ${controller.currentMediaItem?.mediaId}" + } errorState.value = PlaybackException( "Video decoding stalled with a full buffer — likely an unsupported codec", @@ -156,6 +199,7 @@ private suspend fun watchForDecodeStall( // drop the stall overlay. Real decoder errors leave the player IDLE with a frozen // playhead, so they never progress here and are left for the STATE_READY listener. if (progressed && errorState.value != null) { + Log.d(ERROR_LOG_TAG) { "Playhead progressed to $position — clearing stall overlay on ${controller.currentMediaItem?.mediaId}" } errorState.value = null } } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/playerPool/ExoPlayerPool.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/playerPool/ExoPlayerPool.kt index c3567da5b9..e38aa51c0a 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/playerPool/ExoPlayerPool.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/playerPool/ExoPlayerPool.kt @@ -117,8 +117,20 @@ class ExoPlayerPool( if (preferredMediaId != null) { val warm = takeWarm(preferredMediaId) if (warm != null) { - Log.d("PlaybackService") { "ExoPlayerPool warm hit: $preferredMediaId" } - return warm + // A warm player can error *after* it was pooled clean — its decoder dies + // asynchronously while paused (emulator surface reclaim, codec loss). releasePlayer + // can't catch that (the error appears post-release), so it's caught here at acquire: + // never hand a stale PlaybackException to a controller. Release the dead player and + // fall through to a clean cold/fresh one — a guaranteed setMediaItem+prepare ahead. + val error = warm.playerError + if (error != null) { + Log.d("PlaybackService") { "ExoPlayerPool discarding errored warm player: $preferredMediaId (${error.errorCodeName})" } + PcmTapRegistry.unregisterPlayer(warm) + warm.release() + } else { + Log.d("PlaybackService") { "ExoPlayerPool warm hit: $preferredMediaId" } + return warm + } } } return coldPool.poll() ?: builder.build(context) @@ -148,6 +160,19 @@ class ExoPlayerPool( mutex.withLock { if (player.isReleased) return@withLock + // A player that errored out (decoder-init failure, decode error) must never be + // returned to either pool. Kept warm, it hands the stale PlaybackException straight + // back to the next acquire of the same URI — the "Can't play this video" flash traced + // to warm-pool reuse. Its failed MediaCodec instance is also suspect. Drop it so the + // pool builds a clean replacement on the next miss. + val error = player.playerError + if (error != null) { + Log.d("PlaybackService") { "ExoPlayerPool dropping errored player: ${player.currentMediaItem?.mediaId} (${error.errorCodeName})" } + PcmTapRegistry.unregisterPlayer(player) + player.release() + return@withLock + } + val mediaId = player.currentMediaItem?.mediaId if (mediaId != null && warmSlotsCap > 0) { // Warm path: keep the player paused but loaded so a quick scroll-back to the diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/service/PlaybackServiceClient.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/service/PlaybackServiceClient.kt index d641cd8d0c..7339bce641 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/service/PlaybackServiceClient.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/playback/service/PlaybackServiceClient.kt @@ -32,6 +32,7 @@ import kotlinx.coroutines.flow.callbackFlow import java.util.concurrent.ExecutorService import java.util.concurrent.Executors import java.util.concurrent.TimeUnit +import java.util.concurrent.atomic.AtomicInteger import kotlin.uuid.ExperimentalUuidApi import kotlin.uuid.Uuid @@ -46,6 +47,13 @@ object PlaybackServiceClient { // video, each lingering for the 60s keep-alive afterwards. val executorService: ExecutorService = Executors.newFixedThreadPool(4) + // Number of MediaControllers currently held alive (prepared and not yet released). Two + // controllers alive for the same videoUri at once is the signature of the decoder-init + // collision that surfaces as a transient "Can't play this video": the second one's + // MediaCodec.start() fails because the first still holds a codec instance. Logged on every + // prepare/release so the overlap is visible in a field logcat. + private val liveControllers = AtomicInteger(0) + fun shutdown() { executorService.shutdown() } @@ -83,7 +91,7 @@ object PlaybackServiceClient { .setConnectionHints(bundle) .buildAsync() - Log.d("PlaybackService") { "Preparing Controller $id $videoUri" } + Log.d("PlaybackService") { "Preparing Controller $id (live=${liveControllers.incrementAndGet()}) $videoUri" } controllerFuture.addListener( { @@ -108,7 +116,7 @@ object PlaybackServiceClient { ) awaitClose { - Log.d("PlaybackService") { "Releasing Controller $id $videoUri" } + Log.d("PlaybackService") { "Releasing Controller $id (live=${liveControllers.decrementAndGet()}) $videoUri" } try { MediaController.releaseFuture(controllerFuture) } catch (e: Exception) {