Intermittent dom/media/test/test_mediarecorder_playback_can_repeat.html | Test timed out.
Categories
(Core :: Audio/Video: Playback, defect, P5)
Tracking
()
People
(Reporter: bogdan_tara, Assigned: alwu)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])
Attachments
(3 files)
+++ This bug was initially created as a clone of Bug #1392945 +++
Filed by: bclary [at] mozilla.com
https://treeherder.mozilla.org/logviewer.html#?job_id=125019585&repo=mozilla-central
|
Reporter | |
Comment 1•6 years ago
|
||
Seeing this on autoland: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=279963932&repo=autoland&lineNumber=4489
[task 2019-12-06T06:44:13.740Z] 06:44:13 INFO - TEST-START | dom/media/test/test_mediarecorder_playback_can_repeat.html
[task 2019-12-06T06:44:13.781Z] 06:44:13 INFO - GECKO(1756) | [Parent 1756, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2019-12-06T06:44:19.319Z] 06:44:19 INFO - GECKO(1756) | [Child 1759, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6823
[task 2019-12-06T06:49:35.158Z] 06:49:35 INFO - TEST-INFO | started process screencapture
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - TEST-INFO | screencapture: exit 0
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - Buffered messages logged at 06:44:13
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - Drawing color 255,0,0,1
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - TEST-PASS | dom/media/test/test_mediarecorder_playback_can_repeat.html | Media recorder stream = canvas stream at the beginning of recording
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - onstart fired successfully
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - Drawing color 0,0,255,1
[task 2019-12-06T06:49:35.266Z] 06:49:35 INFO - Drawing color 0,0,255,1
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - Buffered messages logged at 06:44:14
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - Drawing color 0,0,255,1
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - Got 'dataavailable' event
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - TEST-PASS | dom/media/test/test_mediarecorder_playback_can_repeat.html | On dataavailable event blob is undefined
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - Got 'stop' event
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - TEST-PASS | dom/media/test/test_mediarecorder_playback_can_repeat.html | Should have gotten a data blob
[task 2019-12-06T06:49:35.267Z] 06:49:35 INFO - Buffered messages finished
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_playback_can_repeat.html | Test timed out.
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.268Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:170:15
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:388:20
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:375:50
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - RunSet.runtests@SimpleTest/setup.js:201:14
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - RunSet.runall@SimpleTest/setup.js:180:12
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - hookupTests@SimpleTest/setup.js:273:12
[task 2019-12-06T06:49:35.269Z] 06:49:35 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
[task 2019-12-06T06:49:35.270Z] 06:49:35 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
[task 2019-12-06T06:49:35.270Z] 06:49:35 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
[task 2019-12-06T06:49:35.270Z] 06:49:35 INFO - hookup@SimpleTest/setup.js:253:20
[task 2019-12-06T06:49:35.270Z] 06:49:35 INFO - EventHandlerNonNull@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2Fcj%2Fpjxvjcl16q9cjktt0r9pg08m000017%2FT&cleanupCrashes=true:11:1
[task 2019-12-06T06:49:36.199Z] 06:49:36 INFO - GECKO(1756) | MEMORY STAT | vsize 7426MB | residentFast 197MB | heapAllocated 28MB
[task 2019-12-06T06:49:36.202Z] 06:49:36 INFO - TEST-OK | dom/media/test/test_mediarecorder_playback_can_repeat.html | took 322473ms
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•6 years ago
|
||
It appears changing to "seeked" didn't help.
After play() we never get "error" or "seeked", even once. This seems like a playback issue to me, possibly related to the loop-seek back to the start.
|
Assignee | |
Comment 4•6 years ago
|
||
Because I couldn't reproduce it on either try server or local environment, I think I will add more debug log first in the test to see if it can give us some insight.
|
|
Assignee | |
Comment 5•6 years ago
|
||
Hmm, I found a weird situation, it seems that even if we dispatched seeked, the video sink was still playing the old video data. Will dig into that more to see what I could find.
|
|
Assignee | |
Comment 6•6 years ago
|
||
Interesting, we actually never seek to the head correctly, and it seems to me that the file didn't get muxed well?
[Child 55046: MediaPlayback #1]: V/MediaFormatReader MediaFormatReader[0x14e2fd000] ::DoVideoSeek: Seeking video to 0
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::GetBuffered: add range 0.000000-1.045000
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMTrackDemuxer[0x1511a8f80] ::Reset: Seek to start point: 0.000000
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::SeekInternal: track_seek for track 0 to 0.000000 failed, r=-1
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::SeekInternal: got offset from buffered state: 481
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::GetNextPacket: push sample tstamp: 1000000 next_tstamp: 1013000 length: 242 kf: 1
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMTrackDemuxer[0x1511a8f80] ::SetNextKeyFrameTime: Next Keyframe 1.000000 (1 queued 0.00s)
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::SeekInternal: track_seek for track 0 to 0.000000 failed, r=-1
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::SeekInternal: got offset from buffered state: 481
[Child 55046: MediaPlayback #1]: V/MediaFormatReader MediaFormatReader[0x14e2fd000] ::ScheduleUpdate: SchedulingUpdate(Video)
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMDemuxer[0x151178400] ::GetNextPacket: push sample tstamp: 1000000 next_tstamp: 1013000 length: 242 kf: 1
[Child 55046: MediaPDecoder #2]: D/MediaDemuxer WebMTrackDemuxer[0x1511a8f80] ::SetNextKeyFrameTime: Next Keyframe 1.000000 (1 queued 0.00s)
From above log (which is a part of the full debug log), we can see that the demuxer failed to seek to 0, and the error came from [1], which seems to be related with not finding a Cues element and we indeed didn't attach Cues in our files. Although we generate a SeekHead in the muxed file, but it seems that we didn't attach correct information into SeekHead. [2]
I don't know if it's a reason of causing this intermittent fail, but I think maybe it worths to figure out whether a recorded file is muxed properly. In addition, I export the recoding to the file [3].
[1] https://searchfox.org/mozilla-central/rev/62a130ba0ac80f75175e4b65536290b52391f116/media/libnestegg/src/nestegg.c#2408
[2] https://searchfox.org/mozilla-central/rev/62a130ba0ac80f75175e4b65536290b52391f116/dom/media/webm/EbmlComposer.cpp#40
[3] https://drive.google.com/file/d/16Tgvxpmik3K4_YPmB9LLh3oSI1Zxkxhf/view?usp=sharing
|
|
Assignee | |
Comment 7•6 years ago
|
||
Hi, kinetik,
Could you give me some insight here? Did we mux a file correctly or we have to fill in the correct information to SeekHead and Cues?
Thank you.
|
|
||
Comment 8•6 years ago
|
||
We don't include cues because we write the header early and (could) hand it to js way before the recording is complete. It's been discussed to write them at the end, but not prioritized. Support for playing webm without cues was added instead, and IIRC seeking has worked in the past. Not as fast as if we had had cues obviously...
|
|
Assignee | |
Comment 9•6 years ago
|
||
Add more log to see (1) if media start playing and (2) if seeking starts, in order to get more information to solve the intermittent failure.
|
||
Comment 10•6 years ago
|
||
Bugbug thinks this bug is a regression, but please revert this change in case of error.
|
|
||
Comment 11•6 years ago
|
||
:alwu, since this bug is a regression, could you fill (if possible) the regressed_by field?
For more information, please visit auto_nag documentation.
|
||
Updated•6 years ago
|
|
|
Assignee | |
Comment 12•6 years ago
|
||
Add more log to see (1) if media start playing and (2) if seeking starts, in order to get more information to solve the intermittent failure.
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 15•6 years ago
|
||
|
|
Reporter | |
Comment 16•6 years ago
|
||
| bugherder | ||
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 18•6 years ago
|
||
We didn't see any failure for a week, so I would close this bug. But feel free to reopen if you see the failure again.
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 20•6 years ago
|
||
Sounds like we know what fixed this.
|
|
||
Comment 21•6 years ago
|
||
| bugherder uplift | ||
https://hg.mozilla.org/releases/mozilla-esr68/rev/3a2605c66013
https://hg.mozilla.org/releases/mozilla-esr68/rev/ae55cf6614e1
Description
•