Skip to content

Repeated BufferAppendErrors switching playback to pause State. Is this hls.js or the stream? #4934

Closed
Closed
Repeated BufferAppendErrors switching playback to pause State. Is this hls.js or the stream?#4934
Labels
BugNeed sample streamcannot reproduce

Description

@agrin96
agrin96
opened on Sep 29, 2022

What do you want to do with Hls.js?

Im not sure this is a bug necessarily, but a client reported a stream having a serious issue. There is a specific segment of VOD content which causes the playback to go crazy. I am not reporting a bug yet because I am not sure if this is simply a very bad stream.

Here is the debug log.

base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 116 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 116 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 116 of track 0 [184.011,234.016]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:612 [log] > [audio-stream-controller]: Loading fragment 117 cc: 0 of [0-2030] track: 0, target: 234.016
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 117 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 117 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 117 of track 0 [184.011,236.000]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 116 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 116 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 116 of level 0 [184.000,234.000]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:612 [log] > [stream-controller]: Loading fragment 117 cc: 0 of [0-2030] level: 0, target: 234
base-stream-controller.ts:1395 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:612 [log] > [audio-stream-controller]: Loading fragment 118 cc: 0 of [0-2030] track: 0, target: 236
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 207.759483 -- S1: [184.010666 -> 234] 
base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 118 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 118 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 118 of track 0 [184.011,238.005]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 117 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 117 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 117 of level 0 [184.000,236.000]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:612 [log] > [stream-controller]: Loading fragment 118 cc: 0 of [0-2030] level: 0, target: 236
base-stream-controller.ts:1395 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:612 [log] > [audio-stream-controller]: Loading fragment 119 cc: 0 of [0-2030] track: 0, target: 238.005
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 119 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 119 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 119 of track 0 [184.011,240.011]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 118 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 118 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 118 of level 0 [184.000,238.000]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:612 [log] > [stream-controller]: Loading fragment 119 cc: 0 of [0-2030] level: 0, target: 238
base-stream-controller.ts:1395 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:612 [log] > [audio-stream-controller]: Loading fragment 120 cc: 0 of [0-2030] track: 0, target: 240.011
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 120 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 120 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 120 of track 0 [184.011,242.016]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 119 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 119 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 119 of level 0 [184.000,240.000]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:612 [log] > [stream-controller]: Loading fragment 120 cc: 0 of [0-2030] level: 0, target: 240
base-stream-controller.ts:1395 [log] > [stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:612 [log] > [audio-stream-controller]: Loading fragment 121 cc: 0 of [0-2030] track: 0, target: 242.016
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: IDLE->FRAG_LOADING
base-stream-controller.ts:373 [log] > [audio-stream-controller]: Loaded fragment 121 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 121 of level 0
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [audio-stream-controller]: Buffered audio sn: 121 of track 0 [184.011,244.000]
base-stream-controller.ts:1395 [log] > [audio-stream-controller]: PARSED->IDLE
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 120 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 120 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
buffer-controller.ts:791 [error] > [buffer-controller]: video SourceBuffer error Event {isTrusted: true, type: 'error', target: SourceBuffer, currentTarget: SourceBuffer, eventPhase: 2, …}
_onSBUpdateError @ buffer-controller.ts:791
PlaybackView.svelte? [sm]:129 HLS.Events.ERROR:  "hlsError" {"type":"mediaError","details":"bufferAppendingError","fatal":false}
buffer-controller.ts:396 [error] > [buffer-controller]: Error encountered while trying to append to the video SourceBuffer Event {isTrusted: true, type: 'error', target: SourceBuffer, currentTarget: SourceBuffer, eventPhase: 2, …}
onError @ buffer-controller.ts:396
_onSBUpdateError @ buffer-controller.ts:802
PlaybackView.svelte? [sm]:129 HLS.Events.ERROR:  "hlsError" {"type":"mediaError","parent":"main","details":"bufferAppendError","err":{"isTrusted":true},"fatal":false}
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 120 of level 0 [184.000,240.040]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
base-stream-controller.ts:1054 [log] > [stream-controller]: SN 120 just loaded, load next one: 121
base-stream-controller.ts:612 [log] > [stream-controller]: Loading fragment 121 cc: 0 of [0-2030] level: 0, target: 242
base-stream-controller.ts:1395 [log] > [stream-controller]: IDLE->FRAG_LOADING
buffer-controller.ts:774 [log] > [buffer-controller]: Media source ended
PlaybackView.svelte? [sm]:392 Media Element error:  {"isTrusted":true}
base-stream-controller.ts:220 [log] > [stream-controller]: media seeking to 212.577, state: FRAG_LOADING
base-stream-controller.ts:220 [log] > [audio-stream-controller]: media seeking to 212.577, state: IDLE
base-stream-controller.ts:220 [log] > [subtitle-stream-controller]: media seeking to 212.577, state: IDLE
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
base-stream-controller.ts:373 [log] > [stream-controller]: Loaded fragment 121 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: FRAG_LOADING->PARSING
buffer-operation-queue.ts:62 [warn] > [buffer-operation-queue]: Unhandled exception executing the current operation
executeNext @ buffer-operation-queue.ts:62
append @ buffer-operation-queue.ts:25
onBufferAppending @ buffer-controller.ts:429
emit @ index.js:182
emit @ hls.ts:253
trigger @ hls.ts:261
bufferFragmentData @ base-stream-controller.ts:743
_handleTransmuxComplete @ stream-controller.ts:1135
handleTransmuxComplete @ transmuxer-interface.ts:332
onWorkerMessage @ transmuxer-interface.ts:291
buffer-controller.ts:396 [error] > [buffer-controller]: Error encountered while trying to append to the video SourceBuffer DOMException: Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.
    at BufferController2.appendExecutor (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3583:18)
    at Object.execute (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3245:26)
    at BufferOperationQueue2.executeNext (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3690:29)
    at BufferOperationQueue2.append (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3658:22)
    at BufferController2.onBufferAppending (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3296:30)
    at EventEmitter.emit (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:162:39)
    at Hls2.emit (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:12841:36)
    at Hls2.trigger (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:12845:29)
    at StreamController2.bufferFragmentData (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:2592:24)
    at StreamController2._handleTransmuxComplete (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:7696:24)
onError @ buffer-controller.ts:396
executeNext @ buffer-operation-queue.ts:65
append @ buffer-operation-queue.ts:25
onBufferAppending @ buffer-controller.ts:429
emit @ index.js:182
emit @ hls.ts:253
trigger @ hls.ts:261
bufferFragmentData @ base-stream-controller.ts:743
_handleTransmuxComplete @ stream-controller.ts:1135
handleTransmuxComplete @ transmuxer-interface.ts:332
onWorkerMessage @ transmuxer-interface.ts:291
PlaybackView.svelte? [sm]:129 HLS.Events.ERROR:  "hlsError" {"type":"mediaError","parent":"main","details":"bufferAppendError","err":{"stack":"Error: Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.\n    at BufferController2.appendExecutor (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3583:18)\n    at Object.execute (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3245:26)\n    at BufferOperationQueue2.executeNext (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3690:29)\n    at BufferOperationQueue2.append (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3658:22)\n    at BufferController2.onBufferAppending (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:3296:30)\n    at EventEmitter.emit (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:162:39)\n    at Hls2.emit (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:12841:36)\n    at Hls2.trigger (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:12845:29)\n    at StreamController2.bufferFragmentData (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:2592:24)\n    at StreamController2._handleTransmuxComplete (http://localhost:5173/node_modules/.vite/deps/hls__js.js?v=30ab8c96:7696:24)"},"fatal":false}
transmuxer-interface.ts:303 [log] > [transmuxer.ts]: Flushed fragment 121 of level 0
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSING->PARSED
base-stream-controller.ts:506 [log] > [stream-controller]: Buffered main sn: 121 of level 0 [184.000,240.040]
base-stream-controller.ts:1395 [log] > [stream-controller]: PARSED->IDLE
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999] 
PlaybackView.svelte? [sm]:57 Memory Usage:  2 %
PlaybackView.svelte? [sm]:66 CurrentTime: 212.577096 -- S1: [184.010666 -> 243.999999]

As you can see after a couple of BufferAppendErrors the CurrentTime stops advancing and buffering ceases. The video element is marked as paused and trying to unpause it causes the player to crash out.

What have you tried so far?

We are running the latest version of hls.js - 1.2.3. I was able to reproduce the original issue on my Brave browser app Version 1.36.112 Chromium: 99.0.4844.51 (Official Build) (x86_64). Note that a BufferAppendingError also occurs in this playback.

I tried adding a playback nudge to the playback which somewhat helped the problem, but it still causes 3-5 errors which require reloading the playback.

As a test I also played the segment in VLC player and there was also a noticeable image drop where the video became gray and artifacted. So to me it seems like this is a problem with the content serving.

If that is the case then my question is how can we effectively handle these types of errors without causing the player to crash? The nudging doesn't really solve the problem well as it causes several playback interruptions before finally settling down.

Any ideas are welcome. Thank you.

Activity

  1. agrin96
    added
    Needs TriageIf there is a suspected stream issue, apply this label to triage if it is something we should fix.
    Question
    on Sep 29, 2022

  2. robwalch commented on Sep 29, 2022

    @robwalch
    robwalch
    on Sep 29, 2022
    Collaborator

    The media element errored. Try using the media inspector in Chrome to get more information.

  3. agrin96 commented on Sep 29, 2022

    @agrin96
    agrin96
    on Sep 29, 2022
    Author

    @robwalch Thanks for that quick reply. I took a look and found this in the errors. It occurs hand in hand with the Append failures.

    

00:00:04.845 | pipeline_state | "kPlaying"
-- | -- | --
00:00:04.911 | pipeline_buffering_state | {"for_suspended_start":false,"state":"BUFFERING_HAVE_ENOUGH"}
00:00:23.803 | error | "Failed to prepare video sample for decode"
00:00:23.803 | error | "Append: stream parsing failed. Data size=131072 append_window_start=0 append_window_end=inf"
00:00:23.803 | pipeline_error | "CHUNK_DEMUXER_ERROR_APPEND_FAILED"
00:00:23.803 | pipeline_state | "kStopping"
00:00:23.803 | pipeline_state | "kStopped"
00:00:23.805 | event | "kPause"
00:00:23.805 | seek_target | 201.639058
00:00:24.487 | event | "kWebMediaPlayerDestroyed"

  4. robwalch commented on Sep 29, 2022

    @robwalch
    robwalch
    on Sep 29, 2022
    Collaborator

    Thanks @agrin96,

    This is either an issue with the media or with how HLS.js muxes it to mp4 if at all. If the segment that produces the error is fmp4 then it is likely a problem with the media. If it's TS then could be either. If you can provide a small sample that reproduces the issue we might be able to look into it further. Try validating playback against other players or media validators first.

  5. agrin96 commented on Sep 29, 2022

    @agrin96
    agrin96
    on Sep 29, 2022
    Author

    I tried it on 2 different devices and a different number of BufferAppendingErrors occured. On my macbook I get 3-4 errors. On a flatscreen tv connected FireStick it gets as high as 10. Im not sure that its a media error specifically. Is it possible to send you a fragment via PM for client confidentiality purposes?

  6. robwalch commented on Sep 29, 2022

    @robwalch
    robwalch
    on Sep 29, 2022
    Collaborator

    By other players I meant video.js or shaka-player.

  7. agrin96 commented on Sep 29, 2022

    @agrin96
    agrin96
    on Sep 29, 2022
    Author

    @robwalch Apologies. I just made a minimal example with the fragment using video.js and I did not encounter any playback issues.

    Edit: I actually just created a minimal hls.js example as well just to be sure and it's looking like this is actually a bug as the playback encountered the error as before.

  8. robwalch
    added
    Bug
    Need sample stream
    and removed
    Question
    Needs TriageIf there is a suspected stream issue, apply this label to triage if it is something we should fix.
    on Sep 30, 2022

  9. agrin96 commented on Oct 1, 2022

    @agrin96
    agrin96
    on Oct 1, 2022
    Author

    @robwalch I set up the source on a dev server so you can take a look. My minimal example code is below. I use svelte + vite. The track starts playing and then stops, while the video.js sample shows no such similar behavior.

    <script lang="ts">
  import Hls from "hls.js"
  import { onMount } from "svelte";

  let videoRef = null;
  let hls = null;
  onMount(() => {
    hls = new Hls()
    hls.loadSource('http://104.194.11.173/16/video-1664452900-180.m3u8?token=ab0c2f')
    hls.attachMedia(videoRef)
    videoRef.play()
  })
</script>

<main>
  <video bind:this={videoRef}></video>
</main>

<style>

</style>

  10. robwalch commented on Apr 9, 2024

    @robwalch
    robwalch
    on Apr 9, 2024
    Collaborator

    Hi @agrin96,

    I'll reopen if you can provide a segment and playlist that reproduce the issue. Thank you.

  11. robwalch
    closed this as completedon Apr 9, 2024
  12. robwalch
    added
    cannot reproduce
    on Apr 9, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    BugNeed sample streamcannot reproduce

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions