Multicast stream get stuck with no error

OrenMe commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Hi @rohitjoins,

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

OrenMe commented 1 year ago

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

giladna commented 1 year ago

@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 commented 1 year ago

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

tomasgarba commented 1 year ago

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 commented 1 year ago

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:

“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 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 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](https://github.com/google/ExoPlayer/files/11273322/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 commented 1 year ago

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 commented 1 year ago

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

tomasgarba commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

@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 commented 1 year ago

@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 commented 1 year ago

I found this which might be relevant https://github.com/google/ExoPlayer/issues/10887

christosts commented 1 year ago

There is a change you're hitting https://github.com/androidx/media/issues/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? https://github.com/androidx/media/issues/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 commented 1 year ago

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 commented 1 year ago

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

OrenMe commented 1 year ago

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 commented 9 months ago

@christosts I see https://github.com/androidx/media/issues/291 has been resolved, can I assume this should solve this issue as well?

christosts commented 9 months ago

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 commented 9 months ago

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 commented 9 months ago

@tonihei do the fix in https://github.com/androidx/media/issues/291 make the player robust of any discrepancy between the audio and video timestamps?

tonihei commented 9 months ago

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 https://github.com/androidx/media/issues/291.

OrenMe commented 9 months ago

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.

google / ExoPlayer