Audio continues to play for ClippingMediaSource while video stuck

[artursahakar]

The issue is observed when using mediaItem list (local mp4 files) where the second media for example has clipStartPosition. With the default mediaCodecSelector(chooses hardware decoder) in the moment of media transition the video frame freezes a little, but then gets updated.

For testing purposes I override MediaCodecSelector where I choose a software decoder. Video freezes but audio plays, after allowedVideoJoiningTimeMs time the player doesn't play anything and the seek in that window doesn't work.

My clipStartPosition values are not keyframes and I expect the transition not to be smooth. Here are some initialization codes.

List<MediaItem> items = new ArrayList<>();
for (MediaData media: medias) {
	items.add(new MediaItem.Builder().setUri(media.getUri())
		.setClipStartPositionMs(media.getTrim().start)
		.setClipEndPositionMs(media.getTrim().end)
		.build()
	 );
}

renderersFactory = new DefaultRenderersFactory(this);
 renderersFactory.setEnableDecoderFallback(true);
videoPlayer = new SimpleExoPlayer.Builder(this, renderersFactory)
		.setTrackSelector(trackSelector).setUseLazyPreparation(false)
		.setLoadControl(new DefaultLoadControl.Builder()
			.setBufferDurationsMs(10_000, 10_000, 1000, 2000)
			.setBackBuffer(2000, false)
			.build())
		.build();
videoPlayer.setmediaitems(items);
videoPlayer.prepare();

Software Decoder - OMX.google.h264.decoder Device Info - [sperry, Moto E (4), motorola, 25] Video info - Video is taken with the devices camera ( for other low res videos the player manages to continue playback) ExoPlayer version - 2.13.3

[artursahakar]

Here's the logs from EventLogger

2021-05-19 20:59:56.579 24927-24927/? D/EventLogger: playWhenReady [eventTime=5.22, mediaPos=0.00, window=0, period=0, true, USER_REQUEST]
2021-05-19 20:59:56.581 24927-24927/? D/EventLogger: isPlaying [eventTime=5.22, mediaPos=0.00, window=0, period=0, true]
2021-05-19 21:00:04.687 24927-24927/? D/EventLogger: videoDisabled [eventTime=13.33, mediaPos=8.03, window=0, period=0]
2021-05-19 21:00:04.690 24927-24927/? D/EventLogger: audioDisabled [eventTime=13.33, mediaPos=8.03, window=0, period=0]
2021-05-19 21:00:04.691 24927-24927/? D/EventLogger: videoEnabled [eventTime=13.33, mediaPos=0.00, window=1, period=1]
2021-05-19 21:00:04.692 24927-24927/? D/EventLogger: audioEnabled [eventTime=13.33, mediaPos=0.00, window=1, period=1]
2021-05-19 21:00:04.694 24927-24927/? D/EventLogger: downstreamFormat [eventTime=13.34, mediaPos=0.00, window=1, period=1, id=1, mimeType=video/avc, codecs=avc1.640028, res=1920x1080, fps=29.938251]
2021-05-19 21:00:04.721 24927-24927/? D/EventLogger: videoDecoderReleased [eventTime=13.36, mediaPos=0.00, window=1, period=1, OMX.google.h264.decoder]
2021-05-19 21:00:04.736 24927-24927/? D/EventLogger: videoDecoderInitialized [eventTime=13.38, mediaPos=0.00, window=1, period=1, OMX.google.h264.decoder]
2021-05-19 21:00:04.737 24927-24927/? D/EventLogger: videoInputFormat [eventTime=13.38, mediaPos=0.00, window=1, period=1, id=1, mimeType=video/avc, codecs=avc1.640028, res=1920x1080, fps=29.938251]
2021-05-19 21:00:04.738 24927-24927/? D/EventLogger: downstreamFormat [eventTime=13.38, mediaPos=0.00, window=1, period=1, id=2, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=48000, language=```]
2021-05-19 21:00:04.744 24927-24927/? D/EventLogger: audioDecoderReleased [eventTime=13.39, mediaPos=0.00, window=1, period=1, OMX.google.aac.decoder]
2021-05-19 21:00:04.771 24927-24927/? D/EventLogger: audioDecoderInitialized [eventTime=13.41, mediaPos=0.00, window=1, period=1, OMX.google.aac.decoder]
2021-05-19 21:00:04.772 24927-24927/? D/EventLogger: audioInputFormat [eventTime=13.41, mediaPos=0.00, window=1, period=1, id=2, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=48000, language=```]
2021-05-19 21:00:04.828 24927-24927/? D/EventLogger: positionDiscontinuity [eventTime=13.47, mediaPos=0.00, window=1, period=1, PERIOD_TRANSITION]
2021-05-19 21:00:04.828 24927-24927/? D/EventLogger: mediaItem [eventTime=13.47, mediaPos=0.00, window=1, period=1, reason=AUTO]
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger: tracks [eventTime=13.47, mediaPos=0.00, window=1, period=1
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:   MediaCodecVideoRenderer [
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:     Group:0, adaptive_supported=N/A [
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:       [X] Track:0, id=1, mimeType=video/avc, codecs=avc1.640028, res=1920x1080, fps=29.938251, supported=NO_EXCEEDS_CAPABILITIES
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:     ]
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:   ]
2021-05-19 21:00:04.829 24927-24927/? D/EventLogger:   MediaCodecAudioRenderer [
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:     Group:0, adaptive_supported=N/A [
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:       [X] Track:0, id=2, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=48000, language=```, supported=YES
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:     ]
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:   ]
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:   TextRenderer []
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:   MetadataRenderer []
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger:   CameraMotionRenderer []
2021-05-19 21:00:04.830 24927-24927/? D/EventLogger: ]
2021-05-19 21:00:09.944 24927-24927/? D/EventLogger: state [eventTime=18.58, mediaPos=5.02, window=1, period=1, BUFFERING]
2021-05-19 21:00:09.944 24927-24927/? D/EventLogger: isPlaying [eventTime=18.59, mediaPos=5.02, window=1, period=1, false]

[krocard]

If I understand the issue correctly:

1. the player is seeking to the next media item
2. because the start position of the video is not an I frame, and a software decoder is used, the video renderer isn't playing immediately
3. after allowedVideoJoiningTimeMs, the video renderer still hasn't played, so it gives up and rederer.isReady() returns false.
4. as a result the player state changes to Buffering (isPlaying == false)

all this is the expected behaviour.

What is not expected, it that playback never resumes and the player is stuck in the buffering state. This seems to indicate an issue with the software decoder and/or the media being decoded.

Could you please attach the media that is sought into and a bug report taken after the bug is produced. It would be of interest to see any codec log.

If you're unable to share bug reports or test content publicly, please send them to [email protected] using a subject in the format "Issue #1234" ("#1234" is replaced with your issue number). Please also update this issue to indicate you've done this.

[tonihei]

Also agree that this sounds media or decoder related.

Two further things to note:

• allowedVideoJoiningTimeMs shouldn't be applied here, instead the player should just enter the buffering state if the newly enabled renderer isn't ready for playback. We had an internal discussion about this recently (@icbaker and me) and were trying to come up with a better solution, but this isn't fully designed yet. Worth marking as a low-priority bug as this is a known problem.
• The renderer support for the video format is marked as NO_EXCEEDS_CAPABILITIES, so it's likely the renderer gets stuck because it can't handle the media format.

[artursahakar]

@krocard Yes the issue is like you described, the player is stuck on buffering on that period, seeking inside that window doesn't help, and it prints this logs.

2021-05-20 13:29:29.234 8135-8135/? D/EventLogger: seekStarted [eventTime=322.99, mediaPos=2.51, window=1, period=1]
2021-05-20 13:29:29.234 8135-8135/? D/EventLogger: positionDiscontinuity [eventTime=322.99, mediaPos=1.48, window=1, period=1, SEEK]
2021-05-20 13:29:29.249 8135-8135/? D/EventLogger: loading [eventTime=323.01, mediaPos=1.48, window=1, period=1, true]
2021-05-20 13:29:29.390 8135-8135/? D/EventLogger: loading [eventTime=323.15, mediaPos=1.48, window=1, period=1, false]

This only happens in playback mode, so if I directly seek on the second window, the player works as expected. Also when the player is stuck on the second video, it normalizes when I seek on the first video

Although the renderer is marked as NO_EXCEEDS_CAPABILITIES it can be played. I think this is more of a decoder problem, the problem is reproducible for all my (1920x1080) videos.

Here's the Video and the Bug Report, here's some Codec logs during media transition

[artursahakar]

I don't know if this helps, but I have a another custom MediaCodecRenderer which is basically your renderer with small changes, which forces the codec to render frames when user scrubs forward ( I don't call seekTo ) , I call the render(long positionUs, long elapsedRealtimeUs) method myself.

With that version, when the second video is stuck and I scrub forward, the player gets unstuck and starts to work.

[tonihei]

@artursahakar I tried to test this using the following setup:

• A playlist with 2 items, both are the video you provided above, stored locally on the device.
• Both playlist items are clipped between arbitrary positions (from 2123ms to 6435ms in my case)
• The DefaultLoadControl was changed as posted above.

I tested on a Pixel 5 and playback works as expected.

• Could you check if the problem occurs on just the Moto E (4) or on other devices as well?
• If my reproduction steps are not accurate, please provide more detailed guidance and what needs to be done to reproduce the problem.

[google-oss-bot]

Hey @artursahakar. We need more information to resolve this issue but there hasn't been an update in 14 weekdays. I'm marking the issue as stale and if there are no new updates in the next 7 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@artursahakar if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.