Closed Bug 1565532 Opened 6 years ago Closed 3 years ago

Intermittent dom/media/test/test_bug1512958.html | Test timed out.

Categories

(Core :: Audio/Video: Playback, defect, P5)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1781568

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [test isolation])

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=256151759&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/TanOzpldTUqtbaxlLPquzA/runs/0/artifacts/public/logs/live_backing.log


INFO - TEST-START | dom/media/test/test_bug1512958.html
10:10:37     INFO - TEST-INFO | started process screenshot
10:10:37     INFO - TEST-INFO | screenshot: exit 0
10:10:37     INFO - Buffered messages logged at 10:05:15
10:10:37     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | A valid string reason is expected 
10:10:37     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | Reason cannot be empty 
10:10:37     INFO - Buffered messages logged at 10:05:16
10:10:37     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | A valid string reason is expected 
10:10:37     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | Reason cannot be empty 
10:10:37     INFO - flac-s24.flac GOT EVENT playing currentTime=0 paused=false ended=false readyState=3
10:10:37     INFO - Buffered messages finished
10:10:37     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_bug1512958.html | Test timed out. 
10:10:37     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
10:10:37     INFO -     reportError@SimpleTest/TestRunner.js:121:22
10:10:37     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:10:37     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
10:10:37     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
10:10:37     INFO -     RunSet.runtests@SimpleTest/setup.js:201:14
10:10:37     INFO -     RunSet.runall@SimpleTest/setup.js:180:12
10:10:37     INFO -     hookupTests@SimpleTest/setup.js:273:12
10:10:37     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:5
10:10:37     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:11
10:10:37     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
10:10:37     INFO -     hookup@SimpleTest/setup.js:253:5
10:10:37     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1562924110%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
10:10:38     INFO - GECKO(5712) | JavaScript error: http://mochi.test:8888/tests/dom/media/test/manifest.js, line 1875: TypeError: a.mozDumpDebugInfo is not a function
10:11:07     INFO - Not taking screenshot here: see the one that was previously logged
10:11:07     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_bug1512958.html | Test timed out. 
10:11:07     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
10:11:07     INFO -     reportError@SimpleTest/TestRunner.js:121:22
10:11:07     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
10:11:07     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
10:11:07     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
10:11:07     INFO -     RunSet.runtests@SimpleTest/setup.js:201:14
10:11:07     INFO -     RunSet.runall@SimpleTest/setup.js:180:12
10:11:07     INFO -     hookupTests@SimpleTest/setup.js:273:12
10:11:07     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:5
10:11:07     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:11
10:11:07     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
10:11:07     INFO -     hookup@SimpleTest/setup.js:253:5
10:11:07     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1562924110%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
10:11:08     INFO - GECKO(5712) | JavaScript error: http://mochi.test:8888/tests/dom/media/test/manifest.js, line 1875: TypeError: a.mozDumpDebugInfo is not a function
10:11:37     INFO - Not taking screenshot here: see the one that was previously logged
10:11:37     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_bug1512958.html | Test timed out. 
Type: -- → defect
Whiteboard: [test isolation]
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=345560058&repo=autoland&lineNumber=4891

[task 2021-07-18T19:22:25.322Z] 19:22:25     INFO - TEST-START | dom/media/test/test_bug1512958.html
[task 2021-07-18T19:22:25.331Z] 19:22:25     INFO - GECKO(5616) | [Child 3896, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-18T19:22:25.335Z] 19:22:25     INFO - GECKO(5616) | [Child 3896, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-18T19:22:25.374Z] 19:22:25     INFO - GECKO(5616) | [Child 3896, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-18T19:22:25.389Z] 19:22:25     INFO - GECKO(5616) | [Child 3896, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-07-18T19:23:15.109Z] 19:23:15     INFO - GECKO(5616) | [Parent 9716, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp:1418
[task 2021-07-18T19:25:10.474Z] 19:25:10     INFO -  [Parent 2428, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/components/places/Database.cpp:516
[task 2021-07-18T19:25:10.474Z] 19:25:10     INFO -  [Parent 2428, Main Thread] WARNING: Unable to get a connection to vacuum database: file /builds/worker/checkouts/gecko/storage/VacuumManager.cpp:130
[task 2021-07-18T19:25:10.492Z] 19:25:10     INFO -  [Parent 2428, IPDL Background] WARNING: QM_TRY failure (ERROR): 'OkIf(gBasePath)', file dom/quota/ActorsParent.cpp:3258
[task 2021-07-18T19:25:10.492Z] 19:25:10     INFO -  [Parent 2428, IPDL Background] WARNING: Trying to create QuotaManager before profile-do-change! Forgot to call do_get_profile()?: file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3257
[task 2021-07-18T19:25:10.493Z] 19:25:10     INFO -  [Parent 2428, IPDL Background] WARNING: QM_TRY failure (ERROR): 'OkIf(quotaManager)', file dom/quota/ActorsParent.cpp:7768
[task 2021-07-18T19:25:15.145Z] 19:25:15     INFO - GECKO(5616) | [Parent 9716, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp:1418
[task 2021-07-18T19:27:15.182Z] 19:27:15     INFO - GECKO(5616) | [Parent 9716, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp:1418
[task 2021-07-18T19:27:42.077Z] 19:27:42     INFO - GECKO(5616) | 1626636462076	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
[task 2021-07-18T19:27:46.881Z] 19:27:46     INFO - TEST-INFO | started process screenshot
[task 2021-07-18T19:27:46.934Z] 19:27:46     INFO - TEST-INFO | screenshot: exit 0
[task 2021-07-18T19:27:46.935Z] 19:27:46     INFO - Buffered messages logged at 19:22:25
[task 2021-07-18T19:27:46.935Z] 19:27:46     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | A valid string reason is expected 
[task 2021-07-18T19:27:46.935Z] 19:27:46     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | Reason cannot be empty 
[task 2021-07-18T19:27:46.936Z] 19:27:46     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | A valid string reason is expected 
[task 2021-07-18T19:27:46.936Z] 19:27:46     INFO - TEST-PASS | dom/media/test/test_bug1512958.html | Reason cannot be empty 
[task 2021-07-18T19:27:46.936Z] 19:27:46     INFO - Buffered messages logged at 19:22:26
[task 2021-07-18T19:27:46.936Z] 19:27:46     INFO - flac-s24.flac GOT EVENT playing currentTime=0 paused=false ended=false readyState=3
[task 2021-07-18T19:27:46.937Z] 19:27:46     INFO - Buffered messages finished
[task 2021-07-18T19:27:46.937Z] 19:27:46     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_bug1512958.html | Test timed out. - 
[task 2021-07-18T19:27:47.977Z] 19:27:47     INFO - {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"PLAYING","channels":2,"containerType":"audio/flac","hasAudio":true,"hasVideo":false,"instance":"1b467427800","rate":88200,"reader":{"audioChannels":2,"audioDecoderName":"ffmpeg audio decoder (RDD remote)","audioFramesDecoded":11,"audioRate":88.19999694824219,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":11,"numSamplesOutput":11,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/flac","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"unavailable","videoHardwareAccelerated":false,"videoHeight":0,"videoNumSamplesOutputTotal":0,"videoNumSamplesSkippedTotal":0,"videoRate":0,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"none","videoWidth":0},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":0,"decodedAudioEndTime":1021677,"decodedVideoEndTime":0,"duration":4040272,"isPlaying":true,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":false,"isStarted":false,"lastGoodPosition":0,"outputRate":0,"playbackComplete":false,"startTime":0,"written":0},"isPlaying":false,"isStarted":false},"decodedStream":{"audioQueueFinished":false,"audioQueueSize":11,"data":{"audioFramesWritten":90112,"haveSentFinishAudio":false,"haveSentFinishVideo":false,"instance":"1b470f5fe60","lastVideoEndTime":-1,"lastVideoStartTime":-1,"nextAudioTime":1021677,"streamAudioWritten":0,"streamVideoWritten":0},"instance":"1b46ff78c00","lastAudio":1021677,"lastOutputTime":0,"playing":1,"startTime":0},"videoSink":{"endPromiseHolderIsEmpty":true,"finished":false,"hasVideo":false,"isPlaying":true,"isStarted":true,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":0,"playState":2,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"idle"}}}
[task 2021-07-18T19:27:48.005Z] 19:27:48     INFO - GECKO(5616) | MEMORY STAT | vsize 2103833MB | vsizeMaxContiguous 67187971MB | residentFast 101MB | heapAllocated 11MB
[task 2021-07-18T19:27:48.017Z] 19:27:48     INFO - TEST-OK | dom/media/test/test_bug1512958.html | took 322695ms
[task 2021-07-18T19:27:48.062Z] 19:27:48     INFO - TEST-START | dom/media/test/test_bug1553262.html
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.