Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=34065579&repo=mozilla-inbound https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-macosx64/1471471466/mozilla-inbound_yosemite_r7_test-web-platform-tests-3-bm136-tests1-macosx-build329.txt.gz

https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=7db02dab044ea63188daa8a1f04ab29647e3b139 here is an example. in the failure case we had 3 06:46:27 INFO - PROCESS | 1661 | [06:46:27.458] vtDecompressionDuctDecodeSingleFrame signalled err=-8969 (err) (VTVideoDecoderDecodeFrame returned error) at /SourceCache/CoreMedia_frameworks/CoreMedia-1562.238/Sources/VideoToolbox/VTDecompressionSession.c line 3241 06:46:27 INFO - PROCESS | 1661 | [06:46:27.476] vtDecompressionDuctDecodeSingleFrame signalled err=-8969 (err) (VTVideoDecoderDecodeFrame returned error) at /SourceCache/CoreMedia_frameworks/CoreMedia-1562.238/Sources/VideoToolbox/VTDecompressionSession.c line 3241 06:46:27 INFO - PROCESS | 1661 | [06:46:27.478] vtDecompressionDuctDecodeSingleFrame signalled err=-8969 (err) (VTVideoDecoderDecodeFrame returned error) at /SourceCache/CoreMedia_frameworks/CoreMedia-1562.238/Sources/VideoToolbox/VTDecompressionSession.c line 3241 We had only one. Getting more than 2 decoding error will cause the element to fire error. Why is it that on the try machine, the h264 decoders sometimes return an error. I can't reproduce it locally on any of the mac.

Surprising it's showing up as intermittent. It should be permanently failing.

The issue is described in bug 1300296. The file being played and used for testing is invalid and has samples incorrectly marked as keyframes. Following the changes to this tests. It now seeks to the 2nd media segments which is invalid. So it seeks to the first frame which can't be decided as its not a keyframe. The Apple VT decoder reports it as a decode error. We then jumps to the next keyframe; which is also invalid as its not really a keyframe. And again. So that's 3 decode errors in a row. My guess with a debug build is that as its slower; the playback starts to run slow and it skip again to next keyframe which is also wrong. And so we reach the threshold allowed for how many consecutive errors we allow. So we can wait for bug 1300296; or recreate this silly MP4 and remux it properly.

P5 might be a tiny bit low for the second-most-frequent single test non-infra failure.

And if we're failing the test because the test file is invalid, then we should certainly fix that.

(In reply to Phil Ringnalda (:philor) from comment #13) > And if we're failing the test because the test file is invalid, then we > should certainly fix that. And we did (bug 1300296) Waiting on the orange factor bot to report that it is indeed fixed.

Heh, time is confusing in every direction, I thought that landed long enough ago that it didn't fix it, but you don't have to wait, since https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1296211 clearly shows that this is... Fixed by bug 1300296.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=155587015&repo=mozilla-inbound&lineNumber=21874 11:09:10 INFO - TEST-START | /media-source/mediasource-seek-during-pending-seek.html 11:09:10 INFO - PID 3376 | ++DOCSHELL 1101BC00 == 16 [pid = 3376] [id = {dfde4913-f6d0-4efb-b9cb-b891677c6fd9}] 11:09:10 INFO - PID 3376 | ++DOMWINDOW == 54 (008F3820) [pid = 3376] [serial = 153] [outer = 00000000] 11:09:10 INFO - PID 3376 | ++DOMWINDOW == 55 (1114C400) [pid = 3376] [serial = 154] [outer = 008F3820] 11:09:10 INFO - PID 3376 | ++DOMWINDOW == 56 (15DD0400) [pid = 3376] [serial = 155] [outer = 008F3820] 11:09:10 INFO - PID 3376 | [DEBUG SHUTDOWN] Register: decoder=273437B0, count=71 11:09:10 INFO - PID 3376 | [DEBUG SHUTDOWN] Register: decoder=273438E0, count=72 11:09:11 INFO - PID 3376 | [3376, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/netwerk/cache2/CacheFileChunk.cpp, line 459 11:09:11 INFO - PID 3376 | [3376, MediaPlayback #5] WARNING: NS_ENSURE_TRUE(SUCCEEDED(hr)) failed: file z:/build/build/src/dom/media/platforms/wmf/WMFUtils.cpp, line 74 11:09:11 INFO - PID 3376 | [3376, MediaPlayback #2] WARNING: NS_ENSURE_TRUE(SUCCEEDED(hr)) failed: file z:/build/build/src/dom/media/platforms/wmf/WMFUtils.cpp, line 74 11:09:11 INFO - PID 3376 | [DEBUG SHUTDOWN] ShutdownDecoder: decoder: 'wmf audio decoder' (15971F60) flush:1 11:09:11 INFO - PID 3376 | [DEBUG SHUTDOWN] ShutdownDecoder: decoder: 'wmf software video decoder - yuv420' (25935180) flush:1 11:09:11 INFO - PID 3376 | [DEBUG SHUTDOWN] operator (): pool=25764E80 shutdown=false count=1 11:09:11 INFO - PID 3376 | [DEBUG SHUTDOWN] operator (): pool=25764E80 shutdown=false count=0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D16DA0 state machine=138FE800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15970 state machine=00830800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15BD0 state machine=0F954800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=0085E250 state machine=00832800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=0085DD90 state machine=138FE000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D167B0 state machine=142C3800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D16680 state machine=142C3000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D16420 state machine=142C2800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D162F0 state machine=142C0000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D161C0 state machine=142BF800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D16090 state machine=142BF000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15F60 state machine=142BC800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15E30 state machine=142BA800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15D00 state machine=142B9800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15AA0 state machine=142B4000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15840 state machine=138EE800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D155E0 state machine=11062800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=15D15120 state machine=1105B000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27343680 state machine=142BD800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27343550 state machine=142B6800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27341670 state machine=142B4800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27730670 state machine=1474D000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27730540 state machine=14740000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27730410 state machine=1473F800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27731E30 state machine=15930800 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27731D00 state machine=15930000 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: decoder=27731BD0 state machine=1592D000 11:09:12 INFO - PID 3376 | --DOMWINDOW == 55 (27712000) [pid = 3376] [serial = 124] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 54 (15C79C00) [pid = 3376] [serial = 121] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 53 (11150400) [pid = 3376] [serial = 122] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 52 (1116A800) [pid = 3376] [serial = 118] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 51 (1114E800) [pid = 3376] [serial = 119] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 50 (11165C00) [pid = 3376] [serial = 115] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 49 (11145000) [pid = 3376] [serial = 116] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 48 (11085800) [pid = 3376] [serial = 112] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 47 (11142800) [pid = 3376] [serial = 113] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 46 (11143400) [pid = 3376] [serial = 109] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 45 (11090400) [pid = 3376] [serial = 110] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 44 (11085C00) [pid = 3376] [serial = 107] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 43 (11083800) [pid = 3376] [serial = 104] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOMWINDOW == 42 (11146C00) [pid = 3376] [serial = 101] [outer = 00000000] [url = about:blank] 11:09:12 INFO - PID 3376 | --DOCSHELL 1F0BE800 == 15 [pid = 3376] [id = {d2e8884d-6202-4cab-ba54-a2a0ac8438c6}] 11:09:12 INFO - PID 3376 | --DOCSHELL 11167C00 == 14 [pid = 3376] [id = {51c0530b-eaad-40b6-8845-9554363f7c87}] 11:09:12 INFO - PID 3376 | --DOCSHELL 11020000 == 13 [pid = 3376] [id = {877e64ec-56c1-4cc7-861e-a13c54a25415}] 11:09:12 INFO - PID 3376 | --DOCSHELL 0C94CC00 == 12 [pid = 3376] [id = {b7ce47d4-adb0-432d-9520-bd9717a76007}] 11:09:12 INFO - PID 3376 | --DOCSHELL 1114E400 == 11 [pid = 3376] [id = {96f54809-a4a8-4f94-b64c-c84c161dad56}] 11:09:12 INFO - PID 3376 | --DOCSHELL 1114B000 == 10 [pid = 3376] [id = {3d66d3b6-84c9-4db3-9134-eb8e81a4795b}] 11:09:12 INFO - PID 3376 | --DOCSHELL 0C94D000 == 9 [pid = 3376] [id = {10f6f2ea-54ec-4ada-877e-71bfede8f9ed}] 11:09:12 INFO - PID 3376 | --DOCSHELL 11012400 == 8 [pid = 3376] [id = {46af9008-7c3f-4e31-8363-9b4c04666fd9}] 11:09:12 INFO - PID 3376 | --DOCSHELL 2770F400 == 7 [pid = 3376] [id = {b3282bda-71c8-4044-80a7-07f131fe5e8b}] 11:09:12 INFO - PID 3376 | --DOCSHELL 11013000 == 6 [pid = 3376] [id = {cb0dfb8a-3d3d-48c1-b7d2-8656e3a60ec8}] 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=0C953D90 reader=1FADCE40 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=0C953FB0 reader=1384E900 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF150 reader=201FD120 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=0C953D78 reader=1F0E56D0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF1B8 reader=1F00FF90 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF220 reader=15C91DD0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF258 reader=15C91970 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF2B8 reader=15C91270 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF2C0 reader=159E2BA0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF2D0 reader=159C4C10 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF2F8 reader=159784A0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF300 reader=159297B0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF320 reader=15929430 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF350 reader=14CCBE40 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF3C8 reader=14CCB580 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF380 reader=14CCBA50 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF400 reader=1FAF7D60 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF420 reader=1FADC9E0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF430 reader=1F0F3CF0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF178 reader=1F03DE40 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF1F8 reader=1F00F350 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF510 reader=2043E740 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF588 reader=226A3200 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF478 reader=20499430 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF5F8 reader=20BF2A50 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF660 reader=20BF2740 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Enter: state machine=101FF508 reader=2043EF90 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: reader=1107A000 shutdown demuxer=159C39F0 11:09:12 INFO - PID 3376 | [DEBUG SHUTDOWN] Shutdown: pool=14CCA340 count=1 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=28319000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] operator (): pool=2572BD60 shutdown=true count=0 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] operator (): pool=25730DC0 shutdown=true count=0 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] operator (): pool=2267BAF0 shutdown=true count=0 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=28884000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=2779D000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=22643000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=28884000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=2779D000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=22643000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=1F095000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=159DF000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=294FF000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=1F095000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=159DF000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=294FF000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=2018F000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=27786000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=28398000 shut down audio task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=27786000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] TearDownDecoders: reader=28398000 shut down video task queue 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FACD000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=20197000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FACB000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FAC7000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=201AC000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FAC5800 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=203B3000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FAC8800 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] FinishShutdown: state machine=1FACF000 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C6B30, count=11 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C67A0, count=10 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=0085D8D0, count=9 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C62E0, count=8 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272BA380, count=7 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C7250, count=6 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272BA250, count=5 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C7120, count=4 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272BA4B0, count=3 11:09:27 INFO - PID 3376 | [DEBUG SHUTDOWN] Unregister: decoder=272C6A00, count=2 11:09:40 INFO - 11:09:40 INFO - TEST-UNEXPECTED-TIMEOUT | /media-source/mediasource-seek-during-pending-seek.html | Test seeking to a new location before transitioning beyond HAVE_METADATA. - Test timed out 11:09:40 INFO - TEST-UNEXPECTED-TIMEOUT | /media-source/mediasource-seek-during-pending-seek.html | expected OK 11:09:40 INFO - TEST-INFO took 30230ms