nextLevel w/ alternative audio track bug

luwes commented 1 year ago

What version of Hls.js are you using?

1.4.10

What browser (including version) are you using?

Chrome Version 115.0.5790.170 (Official Build) (arm64)

What OS (including version) are you using?

MacOS

Test stream

https://hlsjs.video-dev.org/demo/?src=https%3A%2F%2Fstream.mux.com%2FSc89iWAyNkhJ3P1rQ02nrEdCFTnfT01CZ2KmaEcxXfB008.m3u8&demoConfig=eyJlbmFibGVTdHJlYW1pbmciOnRydWUsImF1dG9SZWNvdmVyRXJyb3IiOnRydWUsInN0b3BPblN0YWxsIjpmYWxzZSwiZHVtcGZNUDQiOmZhbHNlLCJsZXZlbENhcHBpbmciOi0xLCJsaW1pdE1ldHJpY3MiOi0xfQ==

Configuration

{
  "debug": true,
  "enableWorker": true,
  "lowLatencyMode": true,
  "backBufferLength": 90
}

Additional player setup steps

No response

Checklist

[X] The issue observed is not already reported by searching on Github under https://github.com/video-dev/hls.js/issues
[X] The issue occurs in the stable client (latest release) on https://hlsjs.video-dev.org/demo and not just on my page
[X] The issue occurs in the latest client (main branch) on https://hlsjs-dev.video-dev.org/demo and not just on my page
[X] The stream has correct Access-Control-Allow-Origin headers (CORS)
[X] There are no network errors such as 404s in the browser console when trying to play the stream

Steps to reproduce

go to https://hlsjs.video-dev.org/demo/
paste in src with MTA https://stream.mux.com/Sc89iWAyNkhJ3P1rQ02nrEdCFTnfT01CZ2KmaEcxXfB008.m3u8
change audio track to commentary (eng)
try to change quality level by choosing Next level loaded 0 (270p)
see it doesn’t change quality in reasonable time

Expected behaviour

that the rendition / level switch happens in a reasonable time

What actually happened?

the rendition / level switch happens but very late, it's like the video buffer is not cleared to make room for the new chosen rendition when an alternative audio track is playing

Console output

Using Hls.js config: {debug: true, enableWorker: true, lowLatencyMode: true, backBufferLength: 90}
logger.ts:74 [log] > Debug logs enabled for "Hls instance" in hls.js version 1.4.10
hls.ts:410 [log] > stopLoad
hls.ts:379 [log] > loadSource:https://stream.mux.com/Sc89iWAyNkhJ3P1rQ02nrEdCFTnfT01CZ2KmaEcxXfB008.m3u8
stream-controller.ts:569 [log] > [stream-controller]: Trigger BUFFER_RESET
hls.ts:351 [log] > attachMedia
buffer-controller.ts:800 [log] > [buffer-controller]: Media source opened
base-stream-controller.ts:1761 [log] > [subtitle-stream-controller]: STOPPED->IDLE
level-controller.ts:269 [log] > [level-controller]: manifest loaded, 4 level(s) found, first bitrate: 2516370
buffer-controller.ts:148 [log] > 2 bufferCodec event(s) expected
hls.ts:400 [log] > startLoad(-1)
level-controller.ts:351 [log] > [level-controller]: Switching to level 2 from level -1
audio-track-controller.ts:138 [log] > [audio-track-controller]: Updating audio tracks, 3 track(s) found in group:aud1
audio-track-controller.ts:195 [log] > [audio-track-controller]: Switching to audio-track 2 "English" lang:en-GB group:aud1

Chrome media internals output

No response

robwalch commented 1 year ago

In this case what would you expect to be a reasonable amount of time, and what length of time have you observed to be very late?

luwes commented 1 year ago

the Apple bip bop stream has the same issue https://devstreaming-cdn.apple.com/videos/streaming/examples/bipbop_16x9/bipbop_16x9_variant.m3u8

see here https://recordit.co/o06l3VY7OH

a reasonable time for switching is like under 15s. it depends how far the buffer was loaded, it seems like it's not clearing the buffer of the previous chosen rendition at all. it could be some minutes.

is this expected behavior? thanks!

robwalch commented 1 year ago

set nextLevel calls streamController.nextLevelSwitch() which depends on getBufferedFrag() to determine what to flush from the fwd buffer. That is coming back null here for some reason:

https://github.com/video-dev/hls.js/blob/5f19df35ae9df5742dd998677f7613ee8b159f90/src/controller/stream-controller.ts#L448-L472

robwalch commented 1 year ago

So the stream producing this issue has audio in the main TS and alt-audio. Switching to alt-audio, and back to the audio in the main playlist, requires the main fragments to be loaded again. For this reason we eject those fragments from the tracker on this kind of audio switch. Only using alt-audio (CMAF) would avoid this issue completely.

https://github.com/video-dev/hls.js/blob/5f19df35ae9df5742dd998677f7613ee8b159f90/src/controller/stream-controller.ts#L789-L796

robwalch commented 1 year ago

I'll leave this confirmed as a bug, but it only impacts TS main muxed with alt-audio. The tracker may remove segments whose video is still buffered after audio coming from that segment is removed, and it has to remove all for which audio is needed but may only have one track buffered (case in point above).

robwalch commented 1 year ago

@luwes,

Let me know how critical this issue is for you. I can suggest workarounds for the recent releases if you need one.

A fix would be more involved and I don't have an easy one in mind for 1.5.

luwes commented 1 year ago

thanks for diagnosing this, I really appreciate it!

it's not very critical I think. yes, please let us know the workarounds. that would be great. we might help out with a fix soon. for now it's fine, I don't think many users will get in this behavior.

robwalch commented 1 year ago

You can workaround the player not flushing by triggering a flush event in your app after setting nextLevel.

hls.trigger(Hls.Events.BUFFER_FLUSHING, { startOffset: video.currentTime + 15, endOffset: Infinity, type: 'video' })

When the player does this flush itself, it triggers this event synchronously upon setting nextLevel, so you could write something that listens for the event and flips a flag to tell if it was called or not. Because it may perform two flushes (back and forward buffer) you need to listen for all events while the setter is evoked:

function smoothSwitch(levelIndex) {
  const currentTime = video.currentTime;
  let flushedFwdBuffer = false;
  const callback = (m, data) => {
    // console.log(m, 'currentTime:', currentTime, data);
    flushedFwdBuffer ||= !Number.isFinite(data.endOffset);
  };
  hls.on(Hls.Events.BUFFER_FLUSHING, callback);
  hls.nextLevel = levelIndex;
  hls.off(Hls.Events.BUFFER_FLUSHING, callback);
  // console.log(flushedFwdBuffer ? 'flushed' : 'did not flush buffer');
  if (!flushedFwdBuffer) {
    hls.trigger(Hls.Events.BUFFER_FLUSHING, { startOffset: currentTime + 15, endOffset: Infinity, type: 'video' });
  }
}

The startOffset could also use some finesse here, but it doesn't have to be exactly on a segment boundary. hls.levels[hls.currentLevel].details.fragments will give you the active playlist segment times, but not necessarily those which were appended at currentTime which we would from the fragmentTracker, but (because of the issue here) were cleared to allow reloading of audio in the main playlist.

It's not pretty, but it gets the job done.

robwalch commented 10 months ago

For this reason we eject those fragments from the tracker on this kind of audio switch

Adding a note that a solution to this issue could be to modify fragment entities in the fragment tracker for the main playlist to denote that audio (but not video) was removed, instead of calling removeAllFragments: https://github.com/video-dev/hls.js/blob/5f19df35ae9df5742dd998677f7613ee8b159f90/src/controller/stream-controller.ts#L789-L796

Then, find everywhere that we use the tracker to determine which fragment is buffered in which SourceBuffer(s) and whether they need to be reloaded for the missing/muxed audio.

Right now, if the tracked main playlist fragment entities were not all removed on muxed to alt audio switch, then they would never be reloaded on the switch back to muxed audio and playback would stall with an empty audio buffer and the player not knowing how to fill it. A simpler fix to this could be to only remove all the segments on the switch back to muxed audio. It's just little unclear whether we're removing everything on both changes or not.

video-dev / hls.js