Multicast stream get stuck with no error

[OrenMe]

ExoPlayer Version

2.18.3

Devices that reproduce the issue

Smartlabs

Devices that do not reproduce the issue

NA

Reproducible in the demo app?

Yes

Reproduction steps

play a multicsat stream when connected to a multicast supported network
same streams sometimes get stuck and sometimes work when switching between them

Expected result

Stream starts playing

Actual result

Stream is stuck randomly after it worked previously, meaning, we played it, changed to other streams and came back to this one and suddenly it is stuck

We observed in the logs errors from codec OMX.amlogic.avc.decoder.awesome2
We tried to troubleshoot the issue - we excluded c2.android.aac.decoder codec and it actually helped to eliminate the issue, streams stopped getting stuck, but this is not a viable solution cause it is on account of having no audio due to excluding of codec.
Side note - also surprisingly, removing the codec helped make the streams loading time a lot faster.

here are some strange lines from logs if multicast is not loaded:

Access denied finding property "media.omx.width"
type=1400 audit(0.0:790): avc: denied { read } for name="u:object_r:default_prop:s0" dev="tmpfs" ino=1004 scontext=u:r:mediacodec:s0 tcontext=u:object_r:default_prop:s0 tclass=file permissive=0
setParameter(0xf083e4d0:amlogic.avc.decoder.awesome2, OMX.google.android.index.allocateNativeHandle(0x7f00000a): Output:1 en=0) ERROR: UnsupportedSetting(0x80001019)
setParameter(0xf083e4d0:amlogic.avc.decoder.awesome2, OMX.google.android.index.storeMetaDataInBuffers(0x7f000002): Output:1 en=1 type=1) ERROR: BadPortIndex(0x8000101b)

what I can see is that by default native buffer info is w:640, h:480 and then some errors while setting resolution:

Access denied finding property "media.omx.width"
Access denied finding property "media.omx.height"

and then

setConfig(0xf083e4d0:amlogic.avc.decoder.awesome2, ConfigPriority(0x6f800002)) ERROR: UnsupportedIndex(0x8000101a)
ACodec                  
com.kaltura.playkitdemo              I  codec does not support config priority (err -1010)

Media

The stream is multicast and can only be tested on multicast network, so can't share working example

Bug Report

• You will email the zip file produced by adb bugreport to dev.exoplayer@gmail.com after filing this issue.

[rohitjoins]

Hi @OrenMe,

The stream is multicast and can only be tested on multicast network, so can't share working example

It might not be straightforward to provide assistance without any input data for us to replicate and evaluate. If you're unable to share bug reports or test content publicly, please send them to dev.exoplayer@gmail.com 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.

[OrenMe]

Hi @rohitjoins , how can I share a multicast stream with you? You need access to the multicast network which requires physical access.
Is there anything else I can provide? We can schedule a session where I can provide remote access somehow through a local machine.

[rohitjoins]

Hi @OrenMe,

Can you repeat your experiments using the demo app and share with us a bug-report. We will be able to get some information from there.

[tomasgarba]

Hi @rohitjoins,

I sent bugreport while playing multicast to email dev.exoplayer@gmail.com.

[OrenMe]

thanks for my team mate @tomasgarba for providing additional info! @rohitjoins does this help to investigate?

[giladna]

@rohitjoins do you have ability to run locally multicast?

I am using this method
ffmpeg -stream_loop -1 -re -i mymulticast.ts -c copy -f mpegts 'udp://239.0.0.1:1024'

let me know if you need ts example via email

[giladna]

@tonihei if you could please have a look at the bug report we sent today via mail
thx!

[tomasgarba]

I can provide some additional logs. While zapping to another channel those are two logs when we get stuck:

multicast-zapping-2023-04-13-2.txt
multicast-zapping-2023-04-13-1.txt

Maybe this is our issue:

AudioFlinger audioserver W createTrack_l(): mismatch between requested flags (00000008)

[maxmashnitsky]

Hello @rohitjoins @christosts

We have analyzed two sessions that play properly and with stuck. We have found two different behavior of the initialization audio. The main issue on the “problematic” behavior is that the selected Audio track is being stopped/crashed after zapping which mainly effect the whole service to crash.

This is mainly explains the change in Audio settings processing/modification by the decoder.

Shown by the logs the process structure been made by the player:

1. “Properly play” use case – after zapping removes/clear the previous audio track and initialize the audio track for a new stream

2023-04-18 16:42:40.456  3292-3357  audio-subMixingFactory              [android.hardware.audio@2.0-service-droidlogic](mailto:android.hardware.audio@2.0-service-droidlogic)  I  [usecase_change_validate_l_sm:1298] cur dev masks:0x1, delete out usecase:[0]PCM_NORMAL
...

2023-04-18 16:42:41.399  3327-11467 AudioFlinger                        audioserver                                    D  createTrack_l format        1
...

2023-04-18 16:42:41.412  3292-6920  audio-subMixingFactory              [android.hardware.audio@2.0-service-droidlogic](mailto:android.hardware.audio@2.0-service-droidlogic)  D  [usecase_change_validate_l_sm:1359] cur dev masks:0, add out usecase:[0]PCM_NORMAL

2. “Stuck” use case – after zapping starts to initialize the new audio track (w/o removing the old one) and deletes the selected audio track (which is the new one) stops the audio initialization.

2023-04-18 16:40:46.244  3327-9196  AudioFlinger                        audioserver                                    D  createTrack_l format        1
...

2023-04-18 16:40:47.765  3292-3357  audio-subMixingFactory              [android.hardware.audio@2.0-service-droidlogic](mailto:android.hardware.audio@2.0-service-droidlogic)  I  [usecase_change_validate_l_sm:1298] cur dev masks:0x1, delete out usecase:[0]PCM_NORMAL

We assume It can be related to not well a re-initialization player on decoder layer on zapping. The Player doesn't fully realize the previous channel and starts to initialize the new channel.

The mentioned logs are attached:
exoplayer_multicast_stack.zip

The archive contains two sessions:

• user-debug-fw-kux-proper-zapping.txt - properly play session;
• user-debug-fw-kux-stuck.txt- stuck session.

[christosts]

While I try to replicate your setup, it sounds like there is an issue with the audio decoder c2.android.aac.decoder. By default, Exoplayer will re-use the decoder between stream switches for faster start-up. Perhaps the device doesn't like that.

Just for clarification, did you try playing the files that you sent to us locally in a playlist on this device? Did you observe any issue with the audio decoder? If there was an issue, that would point to a problem on the device. Otherwise, there may be something in the way the video is transported over UDP, or the player extracts the UDP stream. Either way, that would require more investigation.

In the meantime, can you tweak your app to use a custom MediaCodecAudioRenderer that always creates a new codec when there is a stream switch? You need to override MediaCodecAudioRenderer.canReuseCodec(). This is how to achieve this:

DefaultRenderersFactory renderersFactory = new DefaultRenderersFactory(context.getApplicationContext()) {
      @Override
      protected void buildAudioRenderers(Context context,
          @ExtensionRendererMode int extensionRendererMode, MediaCodecSelector mediaCodecSelector,
          boolean enableDecoderFallback, AudioSink audioSink, Handler eventHandler,
          AudioRendererEventListener eventListener, ArrayList<Renderer> out) {
        out.add(new MediaCodecAudioRenderer(
            context,
            getCodecAdapterFactory(),
            mediaCodecSelector,
            enableDecoderFallback,
            eventHandler,
            eventListener,
            audioSink){
          @Override
          protected DecoderReuseEvaluation canReuseCodec(MediaCodecInfo codecInfo, Format oldFormat,
              Format newFormat) {
            return new DecoderReuseEvaluation(
                codecInfo.name,
                oldFormat,
                newFormat,
                REUSE_RESULT_NO,
                DecoderReuseEvaluation.DISCARD_REASON_APP_OVERRIDE);
          }
        });
      }
    };
ExoPlayer exoPlayer = new ExoPlayer.Builder(context, renderersFactory).build();

[christosts]

[I accidentally closed the issue, it's open now]

[tomasgarba]

Hi @christosts

I've tried your suggestion and set custom rendersFactory and I override canReuseCodec function and double-check while running in debug mode that code stop at this line. Unfortunately I was still able to reproduce stuck issue. Sending logs while zapping https://www.dropbox.com/t/J3durrCVfwWng1dq

[christosts]

• What is the difference between the "correct-log" and "stuck-log"?
• Are these logs captured with the ExoPlayer demo app or your own app? I do see the EventLogger logs but I'm not sure it's the demo app emitting them or if you attached the EventLogger on your app.

I'm streaming the ts files provided to us with ffmpeg on mac (version N-110330-gc17e33c058-tessus) with media3 1.0.1 (ExoPlayer 2.18.6). I see many audio timestamp discontinuities and frequently the player crashes to parse the incoming stream. You do not seem to have such issues, at least not your logs.

[OrenMe]

We have been sharing a few logs but everything done lately is with exoplayer demo app.
@tomasgarba can you please comment on the other questions.

[maxmashnitsky]

@christosts
We have done additional test and found the issue:

• the stuck use case has negative mediaPos for the audio;
• the proper use case has logged with events video: renderedFirstFrame and audio: delete out usecase and add usecase. But the stuck case has only audio: delete out usecase. They are highlighted in the logs below.
• the video stuck, after 49 frames and stop to fill up buffer and not able to render first frame.

The full is attached. The stuck sessions has been started: 04-21 19:36:47.019

Filtered logs of proper session:

04-21 19:36:38.467  8085  8085 D EventLogger: audioDecoderReleased [eventTime=9.00, mediaPos=3.43, window=0, period=0, ffmpegLavc58.54.100-aac]
04-21 19:36:38.468  8085  8085 D EventLogger: videoDecoderReleased [eventTime=9.00, mediaPos=3.43, window=0, period=0, OMX.amlogic.avc.decoder.awesome2]
04-21 19:36:39.526  8085  8085 D EventLogger: videoDecoderInitialized [eventTime=0.71, mediaPos=0.00, window=0, period=0, OMX.amlogic.avc.decoder.awesome2]
04-21 19:36:39.527  8085  8085 D EventLogger: videoInputFormat [eventTime=0.71, mediaPos=0.00, window=0, period=0, id=1/33, mimeType=video/avc, codecs=avc1.64002A, res=1920x1080]
04-21 19:36:39.531  8085  8085 D EventLogger: audioDecoderInitialized [eventTime=0.72, mediaPos=0.00, window=0, period=0, ffmpegLavc58.54.100-aac]
04-21 19:36:39.532  8085  8085 D EventLogger: audioInputFormat [eventTime=0.72, mediaPos=0.00, window=0, period=0, id=1/34, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=24000, language=cs]
04-21 19:36:39.600  8085  8085 D EventLogger: renderedFirstFrame [eventTime=0.79, mediaPos=0.00, window=0, period=0, Surface(name=null)/@0xff8f200]
04-21 19:36:41.733  3297  3297 I audio-subMixingFactory: [usecase_change_validate_l_sm:1298] cur dev masks:0x1, delete out usecase:[0]PCM_NORMAL
04-21 19:36:44.178  3297  5378 I audio-subMixingFactory: usecase_change_validate_l_sm(), add usecase [0]PCM_NORMAL, cnt 1

Filtered logs of stuck session:

04-21 19:36:46.764  8085  8085 D EventLogger: audioDecoderReleased [eventTime=7.95, mediaPos=2.33, window=0, period=0, ffmpegLavc58.54.100-aac]
04-21 19:36:46.764  8085  8085 D EventLogger: videoDecoderReleased [eventTime=7.95, mediaPos=2.33, window=0, period=0, OMX.amlogic.avc.decoder.awesome2]
04-21 19:36:47.605  8085  8085 D EventLogger: videoDecoderInitialized [eventTime=0.40, mediaPos=0.00, window=0, period=0, OMX.amlogic.avc.decoder.awesome2]
04-21 19:36:47.606  8085  8085 D EventLogger: videoInputFormat [eventTime=0.40, mediaPos=0.00, window=0, period=0, id=1/33, mimeType=video/avc, codecs=avc1.64002A, res=1920x1080]
04-21 19:36:47.610  8085  8085 D EventLogger: audioDecoderInitialized [eventTime=0.40, mediaPos=0.00, window=0, period=0, ffmpegLavc58.54.100-aac]
04-21 19:36:47.610  8085  8085 D EventLogger: audioInputFormat [eventTime=0.40, mediaPos=-2.63, window=0, period=0, id=1/34, mimeType=audio/mp4a-latm, codecs=mp4a.40.2, channels=2, sample_rate=24000, language=cs]
04-21 19:36:50.147  3297  3297 I audio-subMixingFactory: [usecase_change_validate_l_sm:1298] cur dev masks:0x1, delete out usecase:[0]PCM_NORMAL

Full logs:
mark-demo-2023-04-21.log

[OrenMe]

@christosts some additional findings, @tomasgarba ran additional test following negative mediaPos for the audio comment by @maxmashnitsky and we see that if we see negative position and we seek to 0 playback is unstuck.
Is there a way to tell exoplayer to overcome this case? if tracks are not aligned does it create a gap that is too big for exo to jump over?

[OrenMe]

I found this which might be relevant #10887

[christosts]

There is a change you're hitting androidx/media#291 So far I have not been able to repro the bug and in your issue description you mentioned this is observed on a Smartlabs device. Have you been able to reproduce on a different device? androidx/media#291 is a bug in the library and should be triggered on different devices. If you only see the issue on the Smartlabs then it's not it.

[OrenMe]

We are also reproducing it on ZTE device so it might be this issue. Is there a way to validate this so I can let you know if it is same? We can try to update the threshold as described and check.

[christosts]

@tonihei in order to verify whether this issue is dup of androidx/media#291, is it sufficient to change the threshold in MediaCodecAudioRenderer to some large(r) value?

[OrenMe]

I'm adding additional analysis:

   The printed logs show what happened when AV decoder sending ts back to exoplayer.  

   In upper red box record normal status, while in below record abnormal status.  

   From the below red box,  we can see the buffer quantity which were available for decoder were decreasing -- from OUT=4/8 to 3/8,  finally to 0/8.   

   Buffer is shared between exoplayer and decoder to transport ts.  x/8  stands for how many were controlled by decoder. 

   0/8 means all the buffer were seized by exoplayer and not release back to decoder.  

      

   AML cannot know why exoplayer stop releasing buffer when stuck happens.  

   AML just guess exoplayer maybe faced some AVsync problem at that time (video were waiting audio for synchronization, so exoplayer finally seized all the buffer). 

   The audio and video timestamp (the stamps were originally sent from exoplayer) have a deviation for more than 4s ,  we can see from the below red box.   

   In comparison, in upper red box,  the AV deviation was less than 600ms.

It sounds like this is similar and we might see here that there should be some stopping condition to overcome this. One simple solution we have now is to seek ahead which probably just locks to another part of the stream which has a shorter drift which is under what exoplayer sees as possible to overcome, or just in line with available codec buffer capability.

[OrenMe]

@christosts I see androidx/media#291 has been resolved, can I assume this should solve this issue as well?

[christosts]

I can't definitely say. Can you repeat you tests with the latest Media3 version? The linked commits were not included in the ExoPlayer project and went into Media3 only.

[OrenMe]

We are planning to run the tests soon as part of the upgrade to media 3.
Where can I find more info on the fix? I want to assume there is some nudging of holes/gaps versus the limited static handling that there was in v2. In general if the av sync gap cannot be met today in the limited 500ms the algorithm gets stuck and there is even no error event. In the case above simple nudge will fix it so there needs to be some re locking logic with some max retry duration to avoid infinite retries in case stream is actually too broken.
The above is somewhat resemble to what shaka player or hls.js player(although both are web players) do to overcome seek holes at start of playbacks

[christosts]

@tonihei do the fix in androidx/media#291 make the player robust of any discrepancy between the audio and video timestamps?

[tonihei]

Yes, but it's impossible to say if it helps with this issue without trying it out :) If someone here can reproduce the issue, please try again with the 1.2.0 release that includes the fixes for androidx/media#291.

[OrenMe]

Thanks, we are planning to do so hopefully by EOW and will update here
We basically see big up to 6 sec gaps and exposed the value so we can pass bigger gap values and some additional improvements but I would prefer a more robust solution indeed.