canalplus / rx-player

DASH/Smooth HTML5 Video Player
https://developers.canal-plus.com/rx-player/
Apache License 2.0
855 stars 130 forks source link

MEDIA_ERR_DECODE errors are being thrown by rxPlayer when starting the stream #1464

Closed TomaszKowalik closed 2 weeks ago

TomaszKowalik commented 3 months ago

Hi We have one STB device on which rxPlayer throws errors when starting the stream. But not always. During my tests, I was getting that error about once per 5 tries. It was happening for both VOD and live content. For live content, sometimes the player catches up and starts playing stream after the error, but not always. I tried DASH + WV and DASH + PR, and I was receiving that error for both combinations. I was getting it for 3.31 and 3.29 rx versions

I was also able to gather some logs:

API: Calling loadvideo https://(...) dash
Locking `contentLock` to clean-up the current content.
DRM: Clearing-up DRM session.
DRM: closing all current sessions.
DRM-LSS: Closing all current MediaKeySessions 0
API: current media element state tick event init position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: playerStateChange event LOADING
API: DRM session cleaned-up with success!
Unlocking `contentLock`. Next content can begin.
Init: Creating ContentDecryptor
DRM: Starting ContentDecryptor logic.
DRM: Searching for compatible MediaKeySystemAccess
DRM: Found cached compatible keySystem
Init: Clearing HTMLMediaElement's src
Init: Creating MediaSource
Init: Attaching MediaSource URL to the media element blob:https://(...)
DASH: WASM MPD Parser not initialized. Running JS one.
MF: Manifest parsed in 43.80000000013388ms
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: current playback timeline:

^0 
timeupdate
Init: MediaSource opened
DRM: Attaching current MediaKeys
Init: Calculating initial time
Init: using startAt.minimumPosition
Init: Initial time calculated: 53
Init: Resume playback speed 1
Init: Updating duration 2556.8
Stream: Creating new Stream for video 0
Stream: Updating video adaptation A: 3 P: 0
SB: Adding native SegmentBuffer with codec video/mp4;codecs="avc1.64000D"
AVSB: calling `mediaSource.addSourceBuffer` video/mp4;codecs="avc1.64000D"
Stream: Creating new Stream for audio 0
Stream: Updating audio adaptation A: 2 P: 0
SB: Adding native SegmentBuffer with codec audio/mp4;codecs="mp4a.40.2"
AVSB: calling `mediaSource.addSourceBuffer` audio/mp4;codecs="mp4a.40.2"
Stream: Creating new Stream for text 0
Stream: Set no text Adaptation. P: 0
Stream: Creating new Stream for image 0
Stream: Set no image Adaptation. P: 0
ABR: Creating new BandwidthEstimator for  video
ABR: Steps for buffer based chooser. bufferLevel: 4, bitrate: 332804 ,bufferLevel: 11.096466766146207, bitrate: 594607 ,bufferLevel: 15.610207009236618, bitrate: 1022231 ,bufferLevel: 19.42873228508276, bitrate: 1510034 ,bufferLevel: 22.074852532174724, bitrate: 1953809 ,bufferLevel: 24.950248206571867, bitrate: 3191394 ,bufferLevel: 29.672458696047222, bitrate: 6700218
ABR: enter starvation mode.
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
Stream: changing representation video video=6700218 6700218
Stream: Media segments now need to be requested. Starting queue. video 11
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: 52-2
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: init
ABR: Creating new BandwidthEstimator for  audio
Stream: changing representation audio audio_eng=129191 129191
Stream: Media segments now need to be requested. Starting queue. audio 11
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: init
DRM: Creating a new temporary session
DRM-LSS: calling `createSession` temporary
DRM-LSS: MediaKeySession added temporary 1
DRM: Binding session events 
DRM-LSS: Reusing session:  temporary
DRM: Init data already processed. Skipping it.
Compat: Calling generateRequest on the MediaKeySession
Compat: Trying to move CENC PSSH from init data at the end of it.
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 3 R: video=6700218 S: init
AVSB: updating codec video/mp4;codecs="avc1.640028"
AVSB: could not update codec video/mp4;codecs="avc1.640028" video/mp4;codecs="avc1.64000D"
AVSB: pushing segment video video P: 1 A: 3 R: video=6700218 S: init
Stream: no more init segment to request. Cancelling queue. video
SF: Segment request cancelled video P: 1 A: 3 R: video=6700218 S: init
SF: Segment request ended with success video P: 1 A: 3 R: video=6700218 S: init
AVSB: receiving order for validating end of segment video video P: 1 A: 3 R: video=6700218 S: init
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: init
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: init
Stream: no more init segment to request. Cancelling queue. audio
SF: Segment request cancelled audio P: 1 A: 2 R: audio_eng=129191 S: init
ABR: New last stable representation 129191
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: init
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: init
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: current playback timeline:

^0 
timeupdate
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
AVSB: Acknowledging complete segment video P: 1 A: 3 R: video=6700218 S: init
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 9000
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
AVSB: setting `appendWindowEnd` 2556.9
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
SI: first segment pushed audio 52.010666666666665 54.016
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: 52.010666666666665-2.005333333333333
SI: found true buffered start audio 52.010666 52.010666666666665
SI: found true buffered end audio 54.015999 54.016
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: init
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
SI: Pushing segment strictly after previous one. audio 54.016 54.015999
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: 54.016-1.984
SI: found true buffered end audio 55.999999 56
SI: current audio inventory timeline:
52.01|A|56.00
[A] P: 1 || R: audio_eng=129191(129191)
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 3 R: video=6700218 S: 52-2
AVSB: updating codec video/mp4;codecs="avc1.640028"
AVSB: could not update codec video/mp4;codecs="avc1.640028" video/mp4;codecs="avc1.64000D"
AVSB: setting `appendWindowEnd` 2556.9
AVSB: pushing segment video video P: 1 A: 3 R: video=6700218 S: 52-2
SF: Segment request ended with success video P: 1 A: 3 R: video=6700218 S: 52-2
AVSB: receiving order for validating end of segment video video P: 1 A: 3 R: video=6700218 S: 52-2
ABR: New last stable representation 6700218
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: 54-2
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: current playback timeline:
52.01|==0.07==|52.08
          ^0 
timeupdate
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
Stream: new video bitrate estimate 11481240.559216026
SI: current audio inventory timeline:
52.01|A|56.00
[A] P: 1 || R: audio_eng=129191(129191)
SI: first segment pushed video 52 54
AVSB: Acknowledging complete segment video P: 1 A: 3 R: video=6700218 S: 52-2
SI: found true buffered start video 52 52
SI: found true buffered end video 54 54
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 12000
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 3 R: video=6700218 S: 54-2
AVSB: updating codec video/mp4;codecs="avc1.640028"
AVSB: could not update codec video/mp4;codecs="avc1.640028" video/mp4;codecs="avc1.64000D"
AVSB: pushing segment video video P: 1 A: 3 R: video=6700218 S: 54-2
SF: Segment request ended with success video P: 1 A: 3 R: video=6700218 S: 54-2
AVSB: receiving order for validating end of segment video video P: 1 A: 3 R: video=6700218 S: 54-2
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: 56-2
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
SI: Pushing segment strictly after previous one. audio 56 55.999999
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: 56-2.005333333333333
SI: found true buffered end audio 58.005333 58.00533333333333
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
API: current media element state tick event loadedmetadata position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 1
API: current playback timeline:
52.01|==2.75==|54.76
          ^0 
loadedmetadata
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
Stream: new video bitrate estimate 16918700.685442306
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
Init: Set initial time 53
API: Seeking internally 53
Init: Can begin to play content
DRM: Received message event, type license-request pr0008
DRM: Calling `getLicense` license-request
API: current media element state tick event internal-seeking position 53 seeking true internalSeek 53 rebuffering false freezing false ended false paused false playbackRate 1 readyState 1
API: current playback timeline:
52.01|==2.95==|54.96
          ^53 
seeking
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
API: current media element state tick event play position 53 seeking true internalSeek 53 rebuffering false freezing false ended false paused false playbackRate 1 readyState 1
API: current playback timeline:
52.01|==2.95==|54.96
          ^53 
play
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
API: current media element state tick event seeked position 53 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
52.01|==3.31==|55.32
          ^53 
seeked
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
API: current media element state tick event canplay position 53 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
52.01|==3.31==|55.32
          ^53 
canplay
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
SI: current audio inventory timeline:
52.01|A|58.01
[A] P: 1 || R: audio_eng=129191(129191)
SI: Pushing segment strictly after previous one. video 54 54
AVSB: Acknowledging complete segment video P: 1 A: 3 R: video=6700218 S: 54-2
SI: found true buffered end video 56 56
SI: current video inventory timeline:
52.00|A|56.00
[A] P: 1 || R: video=6700218(6700218)
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 15000
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 3 R: video=6700218 S: 56-2
AVSB: updating codec video/mp4;codecs="avc1.640028"
AVSB: could not update codec video/mp4;codecs="avc1.640028" video/mp4;codecs="avc1.64000D"
AVSB: pushing segment video video P: 1 A: 3 R: video=6700218 S: 56-2
SF: Segment request ended with success video P: 1 A: 3 R: video=6700218 S: 56-2
AVSB: receiving order for validating end of segment video video P: 1 A: 3 R: video=6700218 S: 56-2
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: 58-2
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
SF: Beginning request audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
SI: Pushing segment strictly after previous one. audio 58.00533333333333 58.005333
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: 58.00533333333333-2.005333333333333
SI: found true buffered end audio 60.010666 60.010666666666665
SI: current audio inventory timeline:
52.01|A|60.01
[A] P: 1 || R: audio_eng=129191(129191)
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
AVSB: pushing segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
SF: Segment request ended with success audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
AVSB: receiving order for validating end of segment audio audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
SI: Pushing segment strictly after previous one. audio 60.010666666666665 60.010666
AVSB: Acknowledging complete segment audio P: 1 A: 2 R: audio_eng=129191 S: 60.010666666666665-2.005333333333333
SI: found true buffered end audio 62.015999 62.016
SI: current audio inventory timeline:
52.01|A|62.02
[A] P: 1 || R: audio_eng=129191(129191)
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 3 R: video=6700218 S: 58-2
SF: Segment request ended with success video P: 1 A: 3 R: video=6700218 S: 58-2
AVSB: receiving order for validating end of segment video video P: 1 A: 3 R: video=6700218 S: 58-2
SF: Beginning request video P: 1 A: 3 R: video=6700218 S: 60-2
SI: Pushing segment strictly after previous one. video 56 56
AVSB: Acknowledging complete segment video P: 1 A: 3 R: video=6700218 S: 56-2
SI: found true buffered end video 58 58
SI: current video inventory timeline:
52.00|A|58.00
[A] P: 1 || R: video=6700218(6700218)
AVSB: updating codec video/mp4;codecs="avc1.640028"
AVSB: could not update codec video/mp4;codecs="avc1.640028" video/mp4;codecs="avc1.64000D"
AVSB: pushing segment video video P: 1 A: 3 R: video=6700218 S: 58-2
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 15000
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
Stream: new video bitrate estimate 20952049.00673543
DRM: Updating MediaKeySession with message
API: current media element state tick event timeupdate position 53 seeking false internalSeek null rebuffering false freezing true ended false paused false playbackRate 1 readyState 2
API: current playback timeline:
52.01|==7.39==|59.40
          ^53 
timeupdate
ABR: Choosing representation with bandwidth estimation. 6700218 video=6700218
SI: current video inventory timeline:
52.00|A|58.00
[A] P: 1 || R: video=6700218(6700218)
SI: current audio inventory timeline:
52.01|A|62.02
[A] P: 1 || R: audio_eng=129191(129191)
SF: Segment request cancelled video P: 1 A: 3 R: video=6700218 S: 60-2
SB: Aborting SegmentBuffer audio
AVSB: Calling `abort` on the SourceBuffer
SB: Aborting SegmentBuffer video
AVSB: Calling `abort` on the SourceBuffer
Init: Aborting SourceBuffer before removing
Init: Removing SourceBuffer from mediaSource
Init: Aborting SourceBuffer before removing
Init: Removing SourceBuffer from mediaSource
Init: Clearing HTMLMediaElement's src
Init: Revoking previous URL
Locking `contentLock` to clean-up the current content.
DRM: Clearing-up DRM session.
DRM: closing all current sessions.
DRM-LSS: Closing all current MediaKeySessions 1
DRM: Trying to close a MediaKeySession pr0008
API: The player stopped because of an error t: MediaError (MEDIA_ERR_DECODE) 
API: playerStateChange event STOPPED

What might be the reason for these errors? In the manifest I can see that for audio codecs are codecs="mp4a.40.2" and for video, depending of representation:

<Representation id="video=332804" bandwidth="332804" width="320" height="180" sar="1:1" codecs="avc1.64000D" scanType="progressive">
      </Representation>
      <Representation id="video=594607" bandwidth="594607" width="484" height="272" sar="1088:1089" codecs="avc1.640015" scanType="progressive">
      </Representation>
      <Representation id="video=1022231" bandwidth="1022231" width="676" height="380" sar="1520:1521" codecs="avc1.64001E" scanType="progressive">
      </Representation>
      <Representation id="video=1510034" bandwidth="1510034" width="854" height="480" sar="2560:2559" codecs="avc1.64001E" scanType="progressive">
      </Representation>
      <Representation id="video=1953809" bandwidth="1953809" width="960" height="540" sar="1:1" codecs="avc1.64001F" scanType="progressive">
      </Representation>
      <Representation id="video=3191394" bandwidth="3191394" width="1280" height="720" sar="1:1" codecs="avc1.64001F" scanType="progressive">
      </Representation>
      <Representation id="video=6700218" bandwidth="6700218" width="1920" height="1080" sar="1:1" codecs="avc1.640028" scanType="progressive">
      </Representation>

I tried to set player.setMaxVideoBitrate(0) but it didnt solved the issue... Btw, once I got : Stream: audio Stream crashed. Stopping playback. t: MediaError (BUFFER_APPEND_ERROR) InvalidStateError: Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null. error

peaBerberian commented 2 months ago

Hi @TomaszKowalik,

Is this only happening on one type of STB device? At around the same time for a given content or does the time not matter?

Is it only happening at the start of the stream or also during playback and do you have a frame visible on the stream before?

TomaszKowalik commented 2 months ago

@peaBerberian

Yes, it's issue that occurs only on that one STB. The time doesn't matter. It seems to be happening only at the start of the stream, and there is no frame visible on the screen. Maybe that's also important: that STB has an Opera browser. We've had that STB for some time, and it was working well with the Rx player, but now this error occurs even on previous stable branches of our app. So, perhaps that's related to the stream's/manifest parameters, but it's really hard to say what might have changed to trigger that error. And in the mentioned scenario for liveStreams - where it first displays error but then catches up and streams - there is black screen when error shows up, but it keeps downloading the segments and eventually starts the stream

peaBerberian commented 2 months ago

The RxPlayer loads a lot of segment at the start of a stream - I can see 12 requests of both audio and video segments in your logs (not surprising but I'm searching for causes).

Maybe is it linked to a memory usage peak and poor memory management on that STB? Or something else linked to the larger amount of data communicated at the start of the stream?

We could test by setting a very low wantedBufferAhead, to only load a few segment at once and see if the issue still happen...

For the:

Stream: audio Stream crashed. Stopping playback. t: MediaError (BUFFER_APPEND_ERROR) InvalidStateError: Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.

You had once, the error tell us that the real issue is the HTMLMediaElement.error attribute being set, probably also to a MEDIA_ERR_DECODE, but it may be that this browser has a race condition that let us know about the resulting BUFFER_APPEND_ERROR before we know about the MEDIA_ERR_DECODE that came before and caused it (e.g. events/errors in the wrong order), I'll also look at if it's possible and if we can better handle such cases (which would still give an error, but the right one).

TomaszKowalik commented 2 months ago

I changed it, but this didn’t result in any improvement :( I also disabled video tracks entirely with player.setPreferredVideoTracks([null]), and the issue still occurred, although it wasn’t downloading any video segments at all (I did the same for audio tracks afterward with the same outcome).

For comparison with other players, I was only able to test it with dash.js on that box, and I wasn’t able to reproduce the issue with it.

Oh, and today, during tests, one time i've seen movie frame (VOD stream), and then error occured and it kicked me out from the stream

peaBerberian commented 2 months ago

OK :/

Maybe is it DRM-related instead? I see that the issue is triggered not long after the license is pushed (DRM: Updating MediaKeySession with message) - even if it appears both with widevine and PlayReady...

We could play with the amount of time taken for the different requests (e.g. through the segmentLoader and getLicense callbacks) to for example ensure the first segment is pushed after the license or much before it and see if it changes the issue's frequency?

Because of the 1/5 reproducibility, it seems to be linked to some time-based conditions,

TomaszKowalik commented 2 months ago

Indeed, it looks like the first segments were being pushed before receiving the license. I delayed pushing segments for some custom amount of time to ensure that the license is acquired, and every time the stream started correctly. However, I did it in a somewhat messy way (as I wanted to check it quickly): we have a custom segment loader implemented only for one environment, and I simply delayed the entire logic there. In other environments, we are not using custom segment and manifest loaders... Do we have any influence on RxPlayer to make it wait for the license before pushing segments?

peaBerberian commented 2 months ago

:tada: OK we found it.


That's very interesting, because we know of another, french-only device (a set-top box provided by a french ISP) with a similar logic.

After exchanging verbally with them, we found out that they on purpose introduced a timeout between the time an encrypted segment is pushed on the buffer and the time at which the license is pushed.

They did this on purpose, so a generic error can be displayed on the screen by the JS application (which would think that there's something wrong with the media being played) instead of potentially having a spinner displayed on the screen for a long time (in which case people would have higher probability to blame their ISP instead - which of course they do not want :P)

Because their timeout was high (close to 10 seconds), we never actually reproduced the issue but still, we were against it and it's against our comprehension of the EME recommendations. So we made our case and as a result it may be fixed on their side (this subject is on-going, but on their side for now).


For your issue, if you have some way to communicate with the people doing the browser integration (especially the DRM-related logic) on that device, it could be a good solution to exchange with them about the issue.

If it's not something you can do, we may have to find another solution like only pushing encrypted segments only once the related license has been pushed. Doing so should be less efficient (longer loading times) than what we're doing now but most of all I fear that it might be hard to maintain. Still, as it seems multiple device providers had the same [bad - at least for us] idea of adding a timeout here, maybe we'll have to find something.

TomaszKowalik commented 2 months ago

Thanks, I'll try to reach out to the STB devs, but it's still quite confusing to me because, as I mentioned before, we were using that box with rx for some time, and it was working fine. This is quite a new issue, and I don't think there was any firmware or browser update on that box that could have triggered it. 🤔Anyway I'll try to get some more info on that topic

TomaszKowalik commented 4 weeks ago

@peaBerberian I don't want to open another almost identical issue, so I'll add it to that one. As for that stb-related bug, we are still waiting for some info; however, I encountered a MEDIA_ERR_DECODE issue with a different device. It is happening with VOD content and seems to be only rxPlayer related. The device is a Philips Smart TV with Titan OS. When starting the stream with pr DRM, RX very often throws a MEDIA_ERR_DECODE error. With wv, it also occurs but significantly less often. I'm not sure if there is anything particular in the logs, I'm attaching them. Could it be possible that RX is missing some DRM support for that device?

Locking `contentLock` to clean-up the current content.
DRM: Clearing-up DRM session.
DRM: closing all current sessions.
DRM-LSS: Closing all current MediaKeySessions 0
API: current media element state tick event init position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: playerStateChange event LOADING
API: DRM session cleaned-up with success!
Unlocking `contentLock`. Next content can begin.
Init: Creating ContentDecryptor
DRM: Starting ContentDecryptor logic.
DRM: Searching for compatible MediaKeySystemAccess
DRM: Found cached compatible keySystem
Init: Clearing HTMLMediaElement's src
Init: Creating MediaSource
Init: Attaching MediaSource URL to the media element blob:https://dev2.solocoo.tv/6516033f-a400-44f2-8c8f-3e2a17d2e2c5
Init: MediaSource opened
DRM: Attaching current MediaKeys
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: current playback timeline:

^0 
timeupdate
DASH: WASM MPD Parser not initialized. Running JS one.
DASH Parser: merging "switchable" AdaptationSets 8 7
MF: Manifest parsed in 157.99999999944703ms
Init: Calculating initial time
Init: using startAt.minimumPosition
Init: Initial time calculated: 7
Init: Resume playback speed 1
Init: Updating duration 7999.04
Stream: Creating new Stream for video 0
Stream: Updating video adaptation A: 7 P: 0
SB: Adding native SegmentBuffer with codec video/mp4;codecs="avc1.4D401E"
AVSB: calling `mediaSource.addSourceBuffer` video/mp4;codecs="avc1.4D401E"
Stream: Creating new Stream for audio 0
Stream: Updating audio adaptation A: 1 P: 0
SB: Adding native SegmentBuffer with codec audio/mp4;codecs="mp4a.40.2"
AVSB: calling `mediaSource.addSourceBuffer` audio/mp4;codecs="mp4a.40.2"
Stream: Creating new Stream for text 0
Stream: Set no text Adaptation. P: 0
Stream: Creating new Stream for image 0
Stream: Set no image Adaptation. P: 0
ABR: Creating new BandwidthEstimator for  video
ABR: Steps for buffer based chooser. bufferLevel: 4, bitrate: 189947 ,bufferLevel: 10.734251628627216, bitrate: 299960 ,bufferLevel: 15.95012631834302, bitrate: 749933 ,bufferLevel: 21.753793766461428, bitrate: 1099940 ,bufferLevel: 24.63540609388732, bitrate: 1499930 ,bufferLevel: 27.27978150945665, bitrate: 2099915 ,bufferLevel: 30.559986139889663, bitrate: 3399914 ,bufferLevel: 33.79501702498114, bitrate: 4499855
ABR: enter starvation mode.
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Stream: changing representation video video=4499855 4499855
Stream: Media segments now need to be requested. Starting queue. video 4
SF: Beginning request video P: 1 A: 7 R: video=4499855 S: 6-6
SF: Beginning request video P: 1 A: 7 R: video=4499855 S: init
ABR: Creating new BandwidthEstimator for  audio
Stream: changing representation audio audio_eng=64000 64000
Stream: Media segments now need to be requested. Starting queue. audio 4
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: init
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 7 R: video=4499855 S: init
AVSB: updating codec video/mp4;codecs="avc1.640029"
AVSB: pushing segment video video P: 1 A: 7 R: video=4499855 S: init
Stream: no more init segment to request. Cancelling queue. video
SF: Segment request cancelled video P: 1 A: 7 R: video=4499855 S: init
SF: Segment request ended with success video P: 1 A: 7 R: video=4499855 S: init
AVSB: receiving order for validating end of segment video video P: 1 A: 7 R: video=4499855 S: init
DRM: Creating a new temporary session
DRM-LSS: calling `createSession` temporary
DRM-LSS: MediaKeySession added temporary 1
DRM: Binding session events 
Compat: Calling generateRequest on the MediaKeySession
Compat: Trying to move CENC PSSH from init data at the end of it.
AVSB: Acknowledging complete segment video P: 1 A: 7 R: video=4499855 S: init
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 9000
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 0
API: current playback timeline:

^0 
timeupdate
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
SF: Segment request ended with success audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 1 R: audio_eng=64000 S: init
AVSB: pushing segment audio audio P: 1 A: 1 R: audio_eng=64000 S: init
Stream: no more init segment to request. Cancelling queue. audio
SF: Segment request cancelled audio P: 1 A: 1 R: audio_eng=64000 S: init
ABR: New last stable representation 64000
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
AVSB: receiving order for validating end of segment audio audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
SF: Segment request ended with success audio P: 1 A: 1 R: audio_eng=64000 S: init
AVSB: receiving order for validating end of segment audio audio P: 1 A: 1 R: audio_eng=64000 S: init
DRM: Creating a new temporary session
DRM-LSS: calling `createSession` temporary
DRM-LSS: MediaKeySession added temporary 2
DRM: Binding session events 
Compat: Calling generateRequest on the MediaKeySession
Compat: Trying to move CENC PSSH from init data at the end of it.
AVSB: setting `appendWindowEnd` 7999.14
AVSB: pushing segment audio audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
SI: first segment pushed audio 6.016 12.010666666666665
AVSB: Acknowledging complete segment audio P: 1 A: 1 R: audio_eng=64000 S: 6.016-5.994666666666666
SI: found true buffered start audio 5.982666 6.016
SI: found true buffered end audio 11.977333 12.010666666666665
AVSB: Acknowledging complete segment audio P: 1 A: 1 R: audio_eng=64000 S: init
API: current media element state tick event loadedmetadata position 0 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 1 readyState 1
API: current playback timeline:

^0 
loadedmetadata
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Init: Set initial time 7
API: Seeking internally 7
API: current media element state tick event internal-seeking position 7 seeking true internalSeek 7 rebuffering true freezing false ended false paused true playbackRate 1 readyState 1
API: current playback timeline:

^7 
seeking
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Init: Pause playback to build buffer
DRM: Received message event, type license-request pr0093
DRM: Calling `getLicense` license-request
API: current media element state tick event ratechange position 7 seeking true internalSeek 7 rebuffering true freezing false ended false paused true playbackRate 0 readyState 1
API: current playback timeline:

^7 
ratechange
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
DRM: Updating MediaKeySession with message
AVSB: receiving order to push data to the SourceBuffer video video P: 1 A: 7 R: video=4499855 S: 6-6
AVSB: setting `appendWindowEnd` 7999.14
AVSB: pushing segment video video P: 1 A: 7 R: video=4499855 S: 6-6
SF: Segment request ended with success video P: 1 A: 7 R: video=4499855 S: 6-6
AVSB: receiving order for validating end of segment video video P: 1 A: 7 R: video=4499855 S: 6-6
ABR: New last stable representation 4499855
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
SF: Beginning request video P: 1 A: 7 R: video=4499855 S: 12-6
DRM: MediaKeySession update succeeded.
DRM: Received message event, type license-request pr0094
DRM: Calling `getLicense` license-request
DRM: keystatuseschange event received pr0093
DRM: key status update (3a793917b2c4a843f9a5eb0393f49a4f): usable
Decipherability changed for "video=4499855" (4499855) true
SI: first segment pushed video 6 12
AVSB: Acknowledging complete segment video P: 1 A: 7 R: video=4499855 S: 6-6
SI: found true buffered start video 6 6
SI: found true buffered end video 12 12
ABR: Incrementing blocking raise in BufferBasedChooser due to unstable quality 12000
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Stream: new video bitrate estimate 17016590.160276696
API: current media element state tick event seeked position 7 seeking false internalSeek null rebuffering false freezing false ended false paused true playbackRate 0 readyState 4
API: current playback timeline:
6.00|==5.98==|11.98
          ^7 
seeked
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Init: Resume playback speed 1
Init: Can begin to play content
API: current media element state tick event canplay position 7 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
6.00|==5.98==|11.98
          ^7 
canplay
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
AVSB: receiving order to push data to the SourceBuffer audio audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
AVSB: pushing segment audio audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
SF: Segment request ended with success audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
AVSB: receiving order for validating end of segment audio audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
API: current media element state tick event ratechange position 7 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
6.00|==5.98==|11.98
          ^7 
ratechange
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
API: current media element state tick event play position 7 seeking false internalSeek null rebuffering false freezing false ended false paused false playbackRate 1 readyState 4
API: current playback timeline:
6.00|==5.98==|11.98
          ^7 
play
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
API: playerStateChange event LOADED
Stream: Updating audio adaptation A: 1 P: 0
Stream: Reusing a previous SegmentBuffer for the type audio
API: playerStateChange event PLAYING
Stream: changing representation audio audio_eng=64000 64000
DRM-LSS: Reusing session: pr0094 temporary
DRM: Init data already processed. Skipping it.
Stream: Media segments now need to be requested. Starting queue. audio 3
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: init
utils.js:1196 13:49:30.741:Rx License server OK
DRM: Updating MediaKeySession with message
SI: Pushing segment strictly after previous one. audio 12.010666666666667 11.977333
API: current media element state tick event timeupdate position 0 seeking false internalSeek null rebuffering false freezing false ended true paused false playbackRate 1 readyState 4
API: current playback timeline:
6.00|==6.00==|12.00
          ^0 
timeupdate
ABR: Choosing representation with bandwidth estimation. 4499855 video=4499855
Stream: Next media segment changed, cancelling previous video
SF: Segment request cancelled video P: 1 A: 7 R: video=4499855 S: 12-6
SF: Beginning request video P: 1 A: 7 R: video=4499855 S: 0-6
SI: found true buffered end audio 17.971999 18.005333333333333
SI: current audio inventory timeline:
5.98|A|18.01
[A] P: 1 || R: audio_eng=64000(64000)
Stream: Next media segment changed, cancelling previous audio
SF: Segment request cancelled audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
SF: Beginning request audio P: 1 A: 1 R: audio_eng=64000 S: 0-6.016
SF: Segment request aborted video P: 1 A: 7 R: video=4499855 S: 12-6
SF: Segment request aborted audio P: 1 A: 1 R: audio_eng=64000 S: 12.010666666666667-5.994666666666666
DRM: MediaKeySession update succeeded.
SF: Segment request cancelled audio P: 1 A: 1 R: audio_eng=64000 S: 0-6.016
SF: Segment request cancelled audio P: 1 A: 1 R: audio_eng=64000 S: init
SF: Segment request cancelled video P: 1 A: 7 R: video=4499855 S: 0-6
SB: Aborting SegmentBuffer audio
AVSB: Calling `abort` on the SourceBuffer
SB: Aborting SegmentBuffer video
AVSB: Calling `abort` on the SourceBuffer
Init: Aborting SourceBuffer before removing
Init: Removing SourceBuffer from mediaSource
Init: Aborting SourceBuffer before removing
Init: Removing SourceBuffer from mediaSource
Init: Clearing HTMLMediaElement's src
Init: Revoking previous URL
Locking `contentLock` to clean-up the current content.
DRM: Clearing-up DRM session.
DRM: closing all current sessions.
DRM-LSS: Closing all current MediaKeySessions 2
DRM: Trying to close a MediaKeySession pr0093
DRM: Trying to close a MediaKeySession pr0094
API: The player stopped because of an error MediaError: MediaError (MEDIA_ERR_DECODE) PIPELINE_ERROR_NETWORK
API: playerStateChange event STOPPED
Locking `contentLock` to clean-up the current content.
DRM: Clearing-up DRM session.
DRM: closing all current sessions.
DRM-LSS: Closing all current MediaKeySessions 0
API: DRM session cleaned-up with success!
Unlocking `contentLock`. Next content can begin.
SF: Segment request aborted audio P: 1 A: 1 R: audio_eng=64000 S: 0-6.016
SF: Segment request aborted audio P: 1 A: 1 R: audio_eng=64000 S: init
SF: Segment request aborted video P: 1 A: 7 R: video=4499855 S: 0-6
DRM: Succeeded to close MediaKeySession
DRM-LSS: session was closed, removing it. pr0093
DRM: Succeeded to close MediaKeySession
API: DRM session cleaned-up with success!
Unlocking `contentLock`. Next content can begin.
DRM-LSS: session was closed, removing it. pr0094
peaBerberian commented 3 weeks ago

Could it be possible that RX is missing some DRM support for that device?

If it was incompatibility of DRM systems, it would probably either be an INCOMPATIBLE_KEYSYSTEMS error or other kinds of ENCRYPTED_MEDIA_ERROR errors, though we've seem sometimes devices fail with what seem to be an unrelated error.

There's here several things that are weird, we first begin at position 7, then we call play and without any seek happening it starts on position 0 for no clear reason.

Then a license is pushed and that's the point at which it fails on a MEDIA_ERR_DECODE. Is the pushed data (video video=4499855, audio audio_eng=64000), supposed to be decipherable in that environment? We've seen devices that just won't accept undecipherable data, despite us having strategies to fallback from them.

We also have some experimental development where we would only push segment we know to be decipherable (https://github.com/canalplus/rx-player/pull/1488) we could test here, like for the initial issue.

TomaszKowalik commented 3 weeks ago

As far as I know, the entire data should be decipherable here. I'm waiting for the device vendor's response on DRM support, as I'm not 100% clear on that matter. The weird part is that it happens quite randomly, and I’ve never seen it on the first attempt to play the asset, but that might just be because I was lucky... Is that experimental feature also available for RX version 3? We haven’t migrated to v4 yet. :(

peaBerberian commented 3 weeks ago

The weird part is that it happens quite randomly, and I’ve never seen it on the first attempt to play the asset, but that might just be because I was lucky...

OK, maybe they have a bug when reusing MediaKeySession instead? Can you try setting the keySystems[].closeSessionsOnStop option to true? (https://developers.canal-plus.com/rx-player/versions/3.33.3/doc/api/Decryption_Options.html#closesessionsonstop)

If it doesn't fix it, we have other work-arounds a little more drastic, as we've often seen some device-specific DRM bugs linked to the device poorly handling decryption setup staying on for multiple contents.

TomaszKowalik commented 3 weeks ago

Ah we are using that option already :( Maybe lets try some other workaround?

peaBerberian commented 3 weeks ago

Do you know how to update the RxPlayer dependency locally? It will be faster to iterate that way.

Though it can be simple in many use cases (just updating the built files) sometimes bundlers add things like caches which mess up with this, but we can add console log calls to check if updates have been taken into account.

So if you can, we may want to just restart negotiation of all decryption mechanisms on each zap, by updating compat/should_renew_media_key_system_access:

Those are the built files, so you should then just have to build and test your application. You can also add a console.log call just to check that the modification is here.

peaBerberian commented 3 weeks ago

If that update doesn't change anything, we may do the same thing with compat/can_reuse_media_keys (should return false), and then if that doesn't work, with compat/should_unset_media_keys.ts (should return true).

TomaszKowalik commented 3 weeks ago

@peaBerberian Actually, we are not using imports, but our player abstraction for Rx relies on an rx.min.js file... However, I manually changed these functions for the version we are currently using and built a custom bundle. And it indeed fixes the issue! (shouldRenewMediaKeySystemAccess). I guess we need to use that build for that device. But could such a change to that function bring any side effects?

peaBerberian commented 3 weeks ago

Nice!

Can you test again just with canReuseMediaKeys, here returning false (as in: "we cannot reuse it")? It would be a little less destructive than shouldRenewMediaKeySystemAccess.

You're seeing this on Philips TVs? Only specific models? We could target the specific platforms to provide a safer default for those TVs, and provide an option for the rest.

TomaszKowalik commented 3 weeks ago

It also seem to be working. This particular device is Philips with TitanOS, its 2023 NT690 4K, but they have different models, and there is a great chance its the issue for all of them... We are detecting that tv group via userAgent, by searching for "WhaleTV"

peaBerberian commented 3 weeks ago

From what I've just seen, "WhaleTV" may also refer to Whale TV OS, which seems to be a different OS?

Maybe it's a new case of putting every previous mention in the user-agent to work-around user agent detection...

If it's TitanOS-specific, I would be more comfortable checking against a TitanOS string or something (and if future/current devices also put that one despite not being titan OS devices and not having the issue, they'll merit having a poorer experience, they should stop messing with that already messy user-agent string!).

TomaszKowalik commented 3 weeks ago

Right, hmm not 100% sure on that topic but I think its rather WhaleTV related. We have only 2023 models, and according to that site, and what I can check in UA, there is no TitanOS in the UA for models lower than 2024. But people who reported that bug experienced it on a 2024 model

peaBerberian commented 3 weeks ago

From what I can read, I don't see any link between whaleOS and TitanOS :/

So maybe they just rely on the same browser integration, which has the same bug, that they ported on both?

From what I found, "Philips NetTV" seems to be their application running a web browser on the device, and it seems to be in the user-agent in both, so they may rely on that software when embedding applications with a browser.

I could try checking for that one, maybe also checking for Philips in the string because NETTV is very generic),

TomaszKowalik commented 3 weeks ago

Ah, perhaps that's the case! I went through some old docs, and there was a proposal for the .*Philips.*NETTV.*WhaleTV/.* regex definition to identify devices we are supporting. So looks like thats around the Philips. Unfortunately, I don't have any other model or different not-Phillips-unit with Titan to clarify it. :(

peaBerberian commented 3 weeks ago

OK thanks!

That documentation comes from Philips? (Which may explain why the WhaleTV mention is still there on TitanOS)

TomaszKowalik commented 3 weeks ago

As I can see it comes from TP Vision, so basically from Philips

peaBerberian commented 3 weeks ago

Thanks, I opened #1515 to try fixing it, it should be easy to backport to our v3.

TomaszKowalik commented 3 weeks ago

Great, thanks! We are currently using rx-player-release-v3.33.4-dev.2024081600. Would it be possible to include these changes also to that branch after merging?

peaBerberian commented 3 weeks ago

We're more likely going to make another pre-release, with the same kind of syntax, once this is merged.

I'll communicate here the version.

TomaszKowalik commented 3 weeks ago

Thanks!

TomaszKowalik commented 2 weeks ago

@peaBerberian This issue is closed, but I wanted to test your solution also for the STB for which I originally created this issue. I changed the canReuseMediaKeys flag again to force it on every zap, and I can’t reproduce the issue anymore! These two devices have in common that they are running Opera (Vewd). It could be a coincidence, but looks like the same fix solves issues on both devices.