ExoPlayer icon indicating copy to clipboard operation
ExoPlayer copied to clipboard

ExoPlaybackException out of the blue

Open giovannyvelezalt opened this issue 2 years ago • 25 comments

ExoPlayer Version

2.16.1

Devices that reproduce the issue

Lots of different brands and models that we couldn't see pattern to put here.

Devices that do not reproduce the issue

No response

Reproducible in the demo app?

No

Reproduction steps

We have been observing a frequent MediaCodecVideoRendererError since 2.16.1 in different devices, so we haven't been able to see a specific pattern regarding devices or OS versions. So we don't have specific reproduction steps. We see it happening on any moment in the user path.

Expected result

Media plays successfully

Actual result

Playback crashes with the following stacktrace:

com.google.android.exoplayer2.ExoPlaybackException: Source error at com.google.android.exoplayer2.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:628) at com.google.android.exoplayer2.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:582) at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:257) at android.os.HandlerThread.run(HandlerThread.java:67) Caused by: com.google.android.exoplayer2.drm.DrmSession$DrmSessionException: com.google.android.exoplayer2.drm.MediaDrmCallbackException: com.google.android.exoplayer2.upstream.HttpDataSource$InvalidResponseCodeException: Response code: 400 at com.google.android.exoplayer2.drm.DefaultDrmSession.onError(DefaultDrmSession.java:540) at com.google.android.exoplayer2.drm.DefaultDrmSession.onProvisionError(DefaultDrmSession.java:243) at com.google.android.exoplayer2.drm.DefaultDrmSessionManager$ProvisioningManagerImpl.onProvisionError(DefaultDrmSessionManager.java:890) at com.google.android.exoplayer2.drm.DefaultDrmSession.onProvisionResponse(DefaultDrmSession.java:397) at com.google.android.exoplayer2.drm.DefaultDrmSession.access$000(DefaultDrmSession.java:60) at com.google.android.exoplayer2.drm.DefaultDrmSession$ResponseHandler.handleMessage(DefaultDrmSession.java:577) at android.os.Handler.dispatchMessage(Handler.java:106) ... 2 more Caused by: com.google.android.exoplayer2.drm.MediaDrmCallbackException: com.google.android.exoplayer2.upstream.HttpDataSource$InvalidResponseCodeException: Response code: 400 at com.google.android.exoplayer2.drm.HttpMediaDrmCallback.executePost(HttpMediaDrmCallback.java:194) at com.google.android.exoplayer2.drm.HttpMediaDrmCallback.executeProvisionRequest(HttpMediaDrmCallback.java:117) at com.quickplay.vstb7.player.internal.f.f.a.executeProvisionRequest(Unknown Source:12) at com.google.android.exoplayer2.drm.DefaultDrmSession$RequestHandler.handleMessage(DefaultDrmSession.java:616) ... 3 more Caused by: com.google.android.exoplayer2.upstream.HttpDataSource$InvalidResponseCodeException: Response code: 400 at com.google.android.exoplayer2.upstream.DefaultHttpDataSource.open(DefaultHttpDataSource.java:396) at com.google.android.exoplayer2.upstream.StatsDataSource.open(StatsDataSource.java:84) at com.google.android.exoplayer2.upstream.DataSourceInputStream.checkOpened(DataSourceInputStream.java:99) at com.google.android.exoplayer2.upstream.DataSourceInputStream.read(DataSourceInputStream.java:79) at com.google.android.exoplayer2.upstream.DataSourceInputStream.read(DataSourceInputStream.java:73) at com.google.android.exoplayer2.util.Util.toByteArray(Util.java:170) at com.google.android.exoplayer2.drm.HttpMediaDrmCallback.executePost(HttpMediaDrmCallback.java:177) ... 6 more

Media

Any Widevine DRM protected content

Bug Report

  • [X] You will email the zip file produced by adb bugreport to [email protected] after filing this issue.

giovannyvelezalt avatar May 30 '22 12:05 giovannyvelezalt

Although we know that HTTP 400 errors are on the license server side we want to know from you the most common causes and also know the causes for the devices don't auto-recover when running into a provisioning error and what can we do to recover from such state.

giovannyvelezalt avatar May 30 '22 15:05 giovannyvelezalt

Are you using the Widevine provisioning service or some other provisioning service? Can you check if the provisioning service URL is valid and if there are no network issues with the device when this error occurs?

Devices that reproduce the issue Lots of different brands and models that we couldn't see pattern to put here.

Is there anything that stands out. Are you seeing this more often on some devices or OS's or even at a particular time (We can check for outages)? Are you able to reproduce it with your app?

We see it happening on any moment in the user path.

This looks like a provisioning error, which should only happen on the start of the first playback. Are you seeing it at other points?

rrfrias avatar May 31 '22 22:05 rrfrias

@rrfrias provisioning calls are being made to an google api

https://www.googleapis.com/certificateprovisioning/v1/devicecertificates/create?key=AIzaSyB-5OLKTx2iU5mko18DfdwK5611JIjbUhE&signedRequest=CskGEgRiBpC9GgQIABIAKpgGCgx3aWRldmluZS5jb20SEFFDT-KkTHY7zCyCai1u-aca4AOp2rMvCafKJb8piqSjKvXIxnsfQQJfXFVozoQQ-DbTqD3ze-EB8y8N4myeK...

ExoPlayer tries it's best to get the device provisioned by making calls for provisioning at every playback start, until it gets success response from provisioning server.

Issues doesn't seem to be happening at particular time, on particular set of devices and OS version. We see 8 to 10 unique users getting affected with this every day on random devices which is why we can't be able to share the time window and info about set of devices that got affected.

We don't think users are getting this provisioning error because of network issues, as users are trying for playback multiple times on multiple days but eventually ends up getting 400 response from the provisioning sever(Users able to play other streaming apps fine). We see provisioning error happening only on start of the playback.

Bhupesh71 avatar Jun 01 '22 13:06 Bhupesh71

Thanks for that information. If a provisioning failure occurs, are users able to successfully provision after one or more retries? A rough idea of the frequency for each of the number of retries before success will be helpful.

Also can you share a few provisioning URLs that failed with [email protected] . I took a look at the bugreports they shared but the provisioning URL was not present.

Internal ref: 234687928

rrfrias avatar Jun 02 '22 07:06 rrfrias

@rrfrias we don't have track for requests to provisioning URL's so can't be able to provide the URL's that failed now. We see 5 to 10 customers everyday facing this issue without getting recovered there after. So it's not possible to provide info regarding frequency for each number of retries before getting success from provisioning call as they are still not able to recover from this issue.

Bhupesh71 avatar Jun 02 '22 16:06 Bhupesh71

Hi Team, Any suggestions on next course of actions for this issue?

Bhupesh71 avatar Jun 10 '22 14:06 Bhupesh71

Hey @giovannyvelezalt. 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 avatar Jun 30 '22 01:06 google-oss-bot

@rrfrias any updates on the issue? If you need any more information to analyse further please let us know.

Bhupesh71 avatar Jul 06 '22 07:07 Bhupesh71

We tried to look at logs at our service to see errors but given the volume were not able to find anything related. Might it be possible for you to share timestamps(and timezone) for HTTP 400 errors for one day to help us narrow down our search for errors. If you can include device make/model, that would help. We also keep logs for a short period of time, so it will be helpful if you share data from at most 3 days ago.

rrfrias avatar Jul 12 '22 22:07 rrfrias

DRM_Provisioning_Error_Device_List.csv

@rrfrias Above is a CSV with the device names and timestamps that encountered the error. All the timestamps are in GMT +0 timezone.

One more peculiar observation we found recently was that all the errors are bound with changes in app versions i.e. a user either starts getting the error on every playback after the app version changes, or a user recovers after app version change. All the starts and ends of these errors are accompanied by an app version change. As indicated earlier, the users are unable to recover from the state no matter what they do (Uninstall / Re install, Clear storage, log in and out, etc). Random devices (inconsistent - different app upgrades seem to fix the issue for different devices) seem to randomly recover from the state when they upgrade the application. There are no changes done on any app version that are related to provisioning.

Please let us know some detailed information about what the application is supposed to do on the DRM front to ensure provisioning during app upgrades.

vishnuchilakala avatar Jul 13 '22 06:07 vishnuchilakala

A device only needs to provision once for a given app. This is unless the app forces it to reprovision. If it stops working after an app upgrade, do you know what fails? a license request? or perhaps an app failure? It should not be a provisioning error. Is provisioning being forced after this error?

Do you see these problems on a small percentage of devices after an app upgrade? And do you see some previously failing devices start to work and other previously working devices start to fail?

rrfrias avatar Jul 14 '22 00:07 rrfrias

Thanks for the quick reply @rrfrias !

If it stops working after an app upgrade, do you know what fails?

After random app upgrades for random devices, we are observing a ERROR_CODE_DRM_PROVISIONING_FAILED at the start of every playback from Exoplayer.

Is provisioning being forced after this error?

We have just the client side logs, which is why we are unable to confirm this. We are definitely getting a ERROR_CODE_DRM_PROVISIONING_FAILED from Exoplayer. I was hoping that the timestamp / device model info that I mentioned in the previous comment would be enough to confirm from the server side if the provisioning calls are indeed being retried and if yes, why they are failing with a 400.

Do you see these problems on a small percentage of devices after an app upgrade? And do you see some previously failing devices start to work and other previously working devices start to fail?

Yes, yes and yes. The error rate is relatively small, but all such users are not able to recover for any subsequent playbacks. To reiterate, after random app upgrades (which have no changes related to DRM / provision), many random devices recover from the error and are able to play. In the same vein, many other random devices start having the error and are unable to play any DRM content until some other random app upgrade fixes the issue.

I am thinking a look at the server side would be our best bet to find any clues. Can you please help us with that? I am attaching the data for the last week of devices that encountered the error. All the timestamps are in GMT +0 timezone. DRM_Provisioning_Error_Last_Week.csv

Please let us know if you need any other kind of info, we would be happy to help. This is a long running production issue and resolving this ASAP would help a ton.

vishnuchilakala avatar Jul 14 '22 13:07 vishnuchilakala

After random app upgrades for random devices, we are observing a ERROR_CODE_DRM_PROVISIONING_FAILED at the start of every playback from Exoplayer.

If the app was provisioned before the update, there should be no reason to provision after. It is surprising that it is happening. And that an attempt is failing. We will look into the latter with the information you share with us. If you can get a bugreport from a device that is experiencing the problem, that might help us with the former.

rrfrias avatar Jul 14 '22 20:07 rrfrias

If you can get a bugreport from a device that is experiencing the problem, that might help us with the former.

Sent two bugreports from the affected devices to [email protected].

Please let us know about your analysis on the server side. Thanks for the help @rrfrias !

vishnuchilakala avatar Jul 15 '22 05:07 vishnuchilakala

I took a look at the bugreports. I could not find any encrypted playback related logs in either bugreport. Did you by any chance capture any of the provisioning requests? That might be helpful.

rrfrias avatar Jul 15 '22 21:07 rrfrias

Sorry, we do not capture any provisioning URLs on our side. This is where I was hoping that the data I gave you regarding the device model & their timestamps might help us in understanding why these requests are returning a 400.

Were you able to track any particular request with the timestamp data? Any clues from the server side?

vishnuchilakala avatar Jul 18 '22 06:07 vishnuchilakala

If you are able to log a few problematic provisioning requests, that would be most helpful.

It is proving a bit difficult to map the device name provided to that specified by the device maker. I have managed to resolve a few and have passed it to my colleagues for furthur analysis. They are looking at it now but even with this information, i have been informed that there is no guarantee that they will be able to find it. Will let you know when i hear back.

rrfrias avatar Jul 19 '22 19:07 rrfrias

We are trying to get bugreports from the customers again. Will let you know when we have any update. @rrfrias any updates on the server side analysis? Were you able to figure out why the requests are failing?

vishnuchilakala avatar Jul 21 '22 11:07 vishnuchilakala

Hi @rrfrias Any new developments / clues on the issue? If you need any more information, please let us know and we will try to procure it.

vishnuchilakala avatar Jul 27 '22 06:07 vishnuchilakala

Hello @rrfrias ! Were you able to find any clues from the provisioning server side?

vishnuchilakala avatar Aug 08 '22 12:08 vishnuchilakala

Thanks for the csv of devices that had provisioning errors. I was not able to find a number of them. It might be that make, model registered by OEMs on some devices does not match the model name you shared.

For the devices i was able to find information for we found that many of the errors are due to invalid or all zero device information in the provisioning request. It seems like these devices should always fail and does not square with information you shared that failures or recovery is associated with app updates.

  • Vivo, 1951
  • Oneplus, OnePlus7TPro (HD1901 and IN2021)
  • Xiaomi, merlin (M2101K6G)

I am waiting on some additional data before we decide on next steps.

rrfrias avatar Aug 09 '22 23:08 rrfrias

Great! Thanks a lot @rrfrias . If you would require any information from our side, feel free to let us know so we can try to get it.

vishnuchilakala avatar Aug 16 '22 06:08 vishnuchilakala

Hello @rrfrias ! Do we have any updates on the issue? Please do let me know. If you need any additional information to analyse further, please do let us know.

P.S. Our issue looks suspiciously similar to #9968 . If you have had any new key insights on that issue, that might also help in our case.

vishnuchilakala avatar Sep 01 '22 13:09 vishnuchilakala

Hello @rrfrias

Please let us know of any updates. Do you need any further information from our side to debug the issue?

vishnuchilakala avatar Sep 15 '22 12:09 vishnuchilakala

The issue is similar to #9968. Since the failed provisioning requests contain garbled data we cannot tell which devices are sending in these requests. Might it be possible to log the failed provisioning request URL and the systemId (use getPropertyString).

rrfrias avatar Sep 21 '22 08:09 rrfrias

Hey @giovannyvelezalt. 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 avatar Oct 11 '22 01:10 google-oss-bot

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

@giovannyvelezalt 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.

google-oss-bot avatar Oct 19 '22 01:10 google-oss-bot