Transmuxing error happening once in a while

[video-dev]

Transmuxing error happening once in a while

[mangui]

is it happening on all browsers, or a specific one ?
providing full debug logs from start would also help.

[AxelDelmas]

Tested on Chrome Ubuntu right now.
I'm trying to repro, I'll get back with more info on other browsers, and logs from hls.js and media-internals

[AxelDelmas]

Repro-ed in Chrome. Here are the logs from media-internals

...
00:33:05 772 duration 2105.7924
00:33:05 772 duration 2106.583288
00:33:05 772 duration 2107.875022
...
00:33:16 443 duration 2117.8332
00:33:16 443 duration 2118.249111
00:33:16 445 debug Generated splice of overlap duration 20355us into new buffer at 2107793644us.
00:33:16 846 duration 2119.084844
00:33:16 847 duration 2119.709733
00:33:26 774 duration 2120.5848
00:33:26 774 duration 2121.666577
00:33:26 774 duration 2122.791377
00:33:26 775 duration 2123.583243
00:33:26 776 duration 2123.601644
00:33:28 507 duration 2124.666799
00:33:28 507 duration 2125.791599
00:33:28 507 duration 2126.750444
00:33:28 508 duration 2128.249154
00:33:28 508 duration 2129.290977
00:33:28 508 duration 2130.874711
00:33:40 383 error Audio splicing failed: coded frame timestamp differs from expected timestamp 2107854691us by -61047us, more than threshold of +/-50ms. Expected timestamp is based on decoded frames and frame rate.
00:33:40 383 error audio decode error during playing
00:33:40 383 pipeline_error pipeline: decode error
00:33:40 383 pipeline_state kStopping
00:33:40 384 pipeline_state kStopped

[mangui]

is it correlated to the crossing of a playlist discontinuity ? do you have hls.js debug logs as well ?

[AxelDelmas]

Here are the logs from hls.js:

Loading 1690 of [1662 ,1691],level 0, currentTime:2068.709472,bufferEnd:2092.381
Demuxing 1690 of [1662 ,1691],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2092.167/2102.584/2092.083/2102.501/250
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2092.134/2102.566/2092.134/2102.566/489
video buffered : [1112.207644,2102.499111]
Loading 1691 of [1662 ,1691],level 0, currentTime:2071.348434,bufferEnd:2102.799
Demuxing 1691 of [1662 ,1691],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2102.584/2107.793/2102.501/2107.793/127
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2102.566/2107.814/2102.566/2107.814/246
video buffered : [1117.135644,2107.792044]
level 0 loaded [1664,1693],duration:183.959
live playlist sliding:1935.751
Loading 1692 of [1664 ,1693],level 0, currentTime:2080.694467,bufferEnd:2108.092
Demuxing 1692 of [1664 ,1693],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2107.834/2118.210/2107.793/2118.168/250
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2107.794/2118.226/2107.794/2118.226/489
video buffered : [1127.567644,2118.166133]
Loading 1693 of [1664 ,1693],level 0, currentTime:2083.48798,bufferEnd:2118.466
Demuxing 1693 of [1664 ,1693],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2118.251/2119.625/2118.168/2119.625/35
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2118.226/2119.698/2118.226/2119.698/69
video buffered : [1129.487644,2119.62471]
level 0 loaded [1666,1695],duration:191.959
live playlist sliding:1938.918
Loading 1694 of [1666 ,1695],level 0, currentTime:2092.694699,bufferEnd:2119.925
Demuxing 1694 of [1666 ,1695],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2119.709/2123.584/2119.625/2123.500/93
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2119.698/2123.602/2119.698/2123.602/183
video buffered : [1133.306311,2123.499243]
Loading 1695 of [1666 ,1695],level 0, currentTime:2093.841636,bufferEnd:2123.799
Demuxing 1695 of [1666 ,1695],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2123.584/2130.835/2123.500/2130.793/175
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2123.602/2130.834/2123.602/2130.834/339
video buffered : [1140.239644,2130.791688]
level 0 loaded [1667,1696],duration:200.583
live playlist sliding:1940.710
Loading 1696 of [1667 ,1696],level 0, currentTime:2104.716132,bufferEnd:2131.092
Demuxing 1696 of [1667 ,1696],level 0
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/2130.876/2141.293/2130.793/2141.210/250
parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/2130.834/2141.266/2130.834/2141.266/489
buffer-controller.js:354 error while trying to append buffer:Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.,try appending latertick @ buffer-controller.js:354onFragParsed @ buffer-controller.js:928EventEmitter.emit @ events.js:80trigger @ hls.js:68onWorkerMessage @ demuxer.js:85
9buffer-controller.js:354 error while trying to append buffer:Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.,try appending latertick @ buffer-controller.js:354setInterval (async)startInternal @ buffer-controller.js:84startLoad @ buffer-controller.js:61onManifestParsed @ buffer-controller.js:784EventEmitter.emit @ events.js:99trigger @ hls.js:68onManifestLoaded @ level-controller.js:82EventEmitter.emit @ events.js:80trigger @ hls.js:68loadsuccess @ playlist-loader.js:174loadsuccess @ xhr-loader.js:63XMLHttpRequest.send (async)loadInternal @ xhr-loader.js:57load @ xhr-loader.js:42load @ playlist-loader.js:43onManifestLoading @ playlist-loader.js:30EventEmitter.emit @ events.js:80trigger @ hls.js:68loadSource @ hls.js:145loadStream @ (index):244(anonymous function) @ (index):194n.event.dispatch @ jquery.min.js:3r.handle @ jquery.min.js:3
buffer-controller.js:794 level 0 loaded [1669,1698],duration:208.583
buffer-controller.js:802 live playlist sliding:1946.959
buffer-controller.js:354 error while trying to append buffer:Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.,try appending latertick @ buffer-controller.js:354onLevelLoaded @ buffer-controller.js:830EventEmitter.emit @ events.js:99trigger @ hls.js:68loadsuccess @ playlist-loader.js:168loadsuccess @ xhr-loader.js:63XMLHttpRequest.send (async)loadInternal @ xhr-loader.js:57load @ xhr-loader.js:42load @ playlist-loader.js:43onLevelLoading @ playlist-loader.js:34EventEmitter.emit @ events.js:80trigger @ hls.js:68tick @ level-controller.js:219setInterval (async)onLevelLoaded @ level-controller.js:211EventEmitter.emit @ events.js:99trigger @ hls.js:68loadsuccess @ playlist-loader.js:168loadsuccess @ xhr-loader.js:63XMLHttpRequest.send (async)loadInternal @ xhr-loader.js:57load @ xhr-loader.js:42load @ playlist-loader.js:43onLevelLoading @ playlist-loader.js:34EventEmitter.emit @ events.js:80trigger @ hls.js:68setLevelInternal @ level-controller.js:117set @ level-controller.js:96set @ hls.js:207tick @ buffer-controller.js:150startLoad @ buffer-controller.js:74onManifestParsed @ buffer-controller.js:784EventEmitter.emit @ events.js:99trigger @ hls.js:68onManifestLoaded @ level-controller.js:82EventEmitter.emit @ events.js:80trigger @ hls.js:68loadsuccess @ playlist-loader.js:174loadsuccess @ xhr-loader.js:63XMLHttpRequest.send (async)loadInternal @ xhr-loader.js:57load @ xhr-loader.js:42load @ playlist-loader.js:43onManifestLoading @ playlist-loader.js:30EventEmitter.emit @ events.js:80trigger @ hls.js:68loadSource @ hls.js:145loadStream @ (index):244(anonymous function) @ (index):194n.event.dispatch @ jquery.min.js:3r.handle @ jquery.min.js:3
13buffer-controller.js:354 error while trying to append buffer:Failed to execute 'appendBuffer' on 'SourceBuffer': The HTMLMediaElement.error attribute is not null.,try appending later

[AxelDelmas]

Seems to be a timestamp error from segment with seqnum 1692

[AxelDelmas]

1691 audio ends at 2107.814
1692 audio starts at 2107.794
so there is an offset of about -20000 micro seconds between both segments, that chrome interprets as an offset of -61047 micro seconds.

In chrome://media-internals log:
...
00:03:27 54 debug Generated splice of overlap duration 20311us into new buffer at 318542666us.
...
00:33:16 445 debug Generated splice of overlap duration 20355us into new buffer at 2107793644us.

I discarded the first line in the first logs I gave as it happened way before the crash, but that amounts to -40666 micro seconds, so a -20381 micro seconds (-20000 if rounded up at the milli second) offset between 1691 and 1692 could have triggered the bug if those sum up

[mangui]

ok do you know if there was a discontinuity tag between 1691 and 1692 ?

[AxelDelmas]

I'm pretty sure there wasn't as I've never seen any in our stream (generated by Wowza). Though I couldn't say, I didn't notice the crash right away as it takes some time to happen.
Is there a log in hls.js if that's the case?

[AxelDelmas]

My guess would be that chrome has handled tiny ~20ms timestamp discontinuities by adding a negative ~20ms offset to all frames starting from the discontinuity, at 00:03:27:540 and 00:33:16:445.

My hypothesis is that there's a bug when it checks for offset < -50ms between two subsequent frames: it checks an offseted timestamp against a non-offseted one, which adds up the chrome offset to the actual frame offset and triggers the error.

[AxelDelmas]

I found this chrome issue: https://code.google.com/p/chromium/issues/detail?id=482085
This looks pretty close to what we're experiencing here.

[mangui]

I am now adjusting the timestamp of overlapping AAC frames. it might avoid this audio decoder issue.

[mangui]

in 20 minutes, I got one audio frame overlapping, with any transmuxer issues :

buffer-controller.js:853 Demuxing 59164 of [59135 ,59164],level 0
buffer-controller.js:909 parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/530.583/535.792/530.500/535.792/127
buffer-controller.js:909 parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/530.565/535.813/530.565/535.813/246

buffer-controller.js:853 Demuxing 59165 of [59138 ,59167],level 0
mp4-remuxer.js:178 AVC:42 ms overlapping between fragments detected
mp4-remuxer.js:185 Video/PTS/DTS adjusted:48225012/48221280
buffer-controller.js:909 parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:video/535.833/546.209/535.792/546.167/250
mp4-remuxer.js:300 AAC:20 ms overlapping between fragments detected
mp4-remuxer.js:304 Audio/PTS/DTS adjusted:48223170/48223170
buffer-controller.js:909 parsed data, type/startPTS/endPTS/startDTS/endDTS/nb:audio/535.813/546.225/535.813/546.225/489

[mangui]

i was able to play the stream for several hours yesterday in chrome without error being raised, closing the ticket

[AxelDelmas]

All right, thanks for the fix!