Player not syncing server with client clock resulting in live stream failures

[grabofus]

Environment

• The MPD passes the DASH-IF Conformance Tool on https://conformance.dashif.org/
• The stream has correct Access-Control-Allow-Origin headers (CORS)
• There are no network errors such as 404s in the browser console when trying to play the stream
• The issue observed is not mentioned on https://github.com/Dash-Industry-Forum/dash.js/wiki/FAQ
• The issue occurs in the latest reference client on http://reference.dashif.org/dash.js/ and not just on my page

• Link to playable MPD file: https://livesim.dashif.org/livesim/testpic_2s/Manifest.mpd
• Dash.js version: 4.0.1 (works as expected in v3.2.2)
• Browser name/version: Chrome / 93
• OS name/version: macOS Catalina

Steps to reproduce

• Change your system clock to run 2 minutes behind or ahead
• Load the stream at: https://reference.dashif.org/dash.js/v4.0.1/samples/live-streaming/live-delay-comparison-custom-manifest.html

Video of reproducing the issue on 4.0.1, and confirming correct behaviour on 3.2.2.
https://sample-videos-zyrkp2nj.s3.eu-west-1.amazonaws.com/20210906_dash_timing/dash_timing_issue_20210906.mp4

Observed behavior

Player should sync client with server clock and load the stream.

Console output

System clock increased by 2 minutes, stream not starting:

[76026][MediaPlayer] Streaming Initialized 
10:39:05.060 Debug.js:169 [76029][EventController] Start Event Controller 
10:39:05.062 Debug.js:169 [76031][MediaPlayer] Playback Initialized 
10:39:05.537 Debug.js:169 [76506][DashParser] Parsing complete: ( xml2json: 1.70ms, objectiron: 0.200ms, total: 0.00190s) 
10:39:05.538 Debug.js:169 [76507][StreamController] Manifest updated... updating data system wide. 
10:39:05.539 Debug.js:169 [76508][StreamController] Matching default timing source protocol to manifest protocol:  https://time.akamai.com/?iso&ms 
10:39:05.540 Debug.js:169 [76509][ManifestUpdater] Manifest has been refreshed at Mon Sep 06 2021 10:39:05 GMT+0100 (British Summer Time)[1630921145.538]  
10:39:05.566 Debug.js:169 [76535][TimeSyncController] Completed UTC sync. Setting client - server offset to -108848 
10:39:05.569 Debug.js:169 [76538][GapController] Starting the gap controller 
10:39:05.569 Debug.js:169 [76538][StreamController] Switch to stream p0. Seektime is 1630921246.416, current playback time is null. Seamless period switch is set to false 
10:39:05.570 Debug.js:169 [76539][StreamController] MediaSource attached to element.  Waiting on open... 
10:39:05.571 Debug.js:169 [76540][StreamController] MediaSource is open! 
10:39:05.572 Debug.js:169 [76541][MediaSourceController] Set MediaSource duration:Infinity 
10:39:05.577 Debug.js:169 [76546][Stream] No text data. 
10:39:05.577 Debug.js:169 [76546][Stream] No muxed data. 
10:39:05.577 Debug.js:169 [76546][Stream] No image data. 
10:39:05.585 Debug.js:169 [76554][PlaybackController] Requesting seek to time: 1630921246.416 (internal) 
10:39:05.588 Debug.js:169 [76557][ScheduleController][video] Quality has changed, get init request for representationid = V300 
10:39:05.589 Debug.js:169 [76558][ScheduleController][audio] Quality has changed, get init request for representationid = A48 
10:39:05.616 Debug.js:169 [76585][TimeSyncController] Completed background UTC sync. Offset is within allowed threshold and is not adjusted. 
10:39:05.677 Debug.js:169 [76646][BufferController][video] Append Init fragment video  with representationId: V300  and quality: 0 , data size: 715 
10:39:05.678 Debug.js:169 [76647][StreamProcessor][video] OnFragmentLoadingCompleted for stream id p0 and media type video - Url: https://livesim.dashif.org/livesim/sts_1630921036/sid_dedcc15e/testpic_2s/V300/init.mp4  
10:39:05.679 Debug.js:169 [76648][ScheduleController][video] Appended bytes for video and stream id p0 
10:39:05.679 Debug.js:169 [76648][ScheduleController][video] [video] lastInitializedRepresentationInfo changed to 0 
10:39:05.679 Debug.js:169 [76648][PlaybackController] Native video element event: play 
10:39:05.680 Debug.js:169 [76649][ManifestUpdater] Refresh manifest in 2147483647 milliseconds. 
10:39:05.680 Debug.js:169 [76649][StreamController] [onPlaybackStarted] 
10:39:05.680 Debug.js:169 [76649][PlaybackController] Native video element event: waiting 
10:39:05.682 Debug.js:169 [76651][ScheduleController][video] Top quality video index has changed from NaN to 0 
10:39:05.682 Debug.js:169 [76651][ScheduleController][video] Media segment needed for video and stream id p0 
10:39:05.682 Debug.js:169 [76651][DashHandler][video] Getting the request for time : 1630921246.416 
10:39:05.764 Debug.js:169 [76733][BufferController][audio] Append Init fragment audio  with representationId: A48  and quality: 0 , data size: 651 
10:39:05.765 Debug.js:169 [76734][StreamProcessor][audio] OnFragmentLoadingCompleted for stream id p0 and media type audio - Url: https://livesim.dashif.org/livesim/sts_1630921036/sid_dedcc15e/testpic_2s/A48/init.mp4  
10:39:05.765 Debug.js:169 [76734][ScheduleController][audio] Appended bytes for audio and stream id p0 
10:39:05.765 Debug.js:169 [76734][ScheduleController][audio] [audio] lastInitializedRepresentationInfo changed to 0 
10:39:05.769 Debug.js:169 [76738][PlaybackController] Native video element event: loadedmetadata 
10:39:05.769 Debug.js:169 [76738][ScheduleController][audio] Top quality audio index has changed from NaN to 0 
10:39:05.769 Debug.js:169 [76738][ScheduleController][audio] Media segment needed for audio and stream id p0 
10:39:05.769 Debug.js:169 [76738][DashHandler][audio] Getting the request for time : 1630921246.416 
10:39:05.924 Debug.js:169 [76893][BufferController][video] Waiting for more buffer before starting playback 
10:39:05.924 Debug.js:169 [76893][BufferController][audio] Waiting for more buffer before starting playback 
10:39:06.183 Debug.js:169 [77152][ScheduleController][video] Media segment needed for video and stream id p0 
10:39:06.270 Debug.js:169 [77239][ScheduleController][audio] Media segment needed for audio and stream id p0 
10:39:06.684 Debug.js:169 [77653][ScheduleController][video] Media segment needed for video and stream id p0 
10:39:06.771 Debug.js:169 [77740][ScheduleController][audio] Media segment needed for audio and stream id p0 
10:39:07.186 Debug.js:169 [78155][ScheduleController][video] Media segment needed for video and stream id p0 
10:39:07.272 Debug.js:169 [78241][ScheduleController][audio] Media segment needed for audio and stream id p0 
10:39:07.687 Debug.js:169 [78656][ScheduleController][video] Media segment needed for video and stream id p0 
10:39:07.773 Debug.js:169 [78742][ScheduleController][audio] Media segment needed for audio and stream id p0 
10:39:08.188 Debug.js:169 [79157][ScheduleController][video] Media segment needed for video and stream id p0 

Expected behavior

In case of decreasing the system clock time the player will play 4 minutes delayed compared to live edge.
In case of increasing the system clock time the player will not start playback or start requesting segments that don't exist yet, resulting in 404s.

[dsilhavy]

Thanks for pointing this out, I deployed a fix for that in #3759. It should be available in nightly soon. Can you please confirm that it fixes the issue.

[dsilhavy]

I refactored this again in 6a0d37c but it should result in the same behavior and this problem should still be fixed.

[grabofus]

I've tested on the reference player, and the issue seems resolved in the nightly build. Thanks for the quick fix!