Closed Bug 1442399 Opened 2 years ago Closed 8 months ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla66
Tracking Status
firefox65 --- fixed
firefox66 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: alwu)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(2 files)

Component: General → Audio/Video: Playback
The consistency in the anaylser results suggests that the MSG may have stalled.
I guess that might also cause the seeking to never start.
Component: Audio/Video: Playback → Audio/Video: MediaStreamGraph
I wonder whether animation frames run at higher priority than other events.
Sorry, I was assuming that "Found unexpected high frequency content" was an error, but that is the expected pass state.
The problem seems more likely related to the seeked events.
Component: Audio/Video: MediaStreamGraph → Audio/Video: Playback
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → INCOMPLETE
Recent failure log : https://treeherder.mozilla.org/logviewer.html#?job_id=179460322&repo=autoland&lineNumber=3289

09:08:42     INFO -  780 INFO TEST-START | dom/media/test/test_seamless_looping.html
09:09:02     INFO -  GECKO(864) | 1526893742283	addons.xpi-utils	WARN	Add-on workerbootstrap-test@mozilla.org is not compatible with application version.
09:14:04     INFO -  TEST-INFO | started process screenshot
09:14:04     INFO -  TEST-INFO | screenshot: exit 0
09:14:04    ERROR -  781 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_seamless_looping.html | Test timed out.
09:14:04     INFO -      reportError@SimpleTest/TestRunner.js:121:7
09:14:04     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
09:14:04     INFO -      TestRunner.runTests@SimpleTest/TestRunner.js:380:5
09:14:04     INFO -      RunSet.runtests@SimpleTest/setup.js:194:3
09:14:04     INFO -      RunSet.runall@SimpleTest/setup.js:173:5
09:14:04     INFO -      hookupTests@SimpleTest/setup.js:266:5
09:14:04     INFO -  parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
09:14:04     INFO -  getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
09:14:04     INFO -  EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
09:14:04     INFO -      hookup@SimpleTest/setup.js:246:5
09:14:04     INFO -  EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1526892467%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
09:14:05     INFO -  GECKO(864) | MEMORY STAT | vsize 2098716MB | vsizeMaxContiguous 129289856MB | residentFast 134MB | heapAllocated 17MB
09:14:05     INFO -  782 INFO TEST-OK | dom/media/test/test_seamless_looping.html | took 323155ms
09:14:05     INFO -  783 INFO TEST-START | dom/media/test/test_seek-1.html
09:14:05     INFO -  GECKO(864) | SEEK-TEST: Started r11025_s16_c1.wav seek test 1
09:14:05     INFO -  GECKO(864) | SEEK-TEST: Started audio.wav seek test 1
09:17:05     INFO -  Not taking screenshot here: see the one that was previously logged
09:17:05     INFO -  Buffered messages logged at 09:14:05
09:17:05     INFO -  784 INFO TEST-PASS | dom/media/test/test_seek-1.html | A valid string reason is expected
09:17:05     INFO -  785 INFO TEST-PASS | dom/media/test/test_seek-1.html | Reason cannot be empty
09:17:05     INFO -  786 INFO Started Mon May 21 2018 09:14:05 GMT+0000 (Coordinated Universal Time) (1526894045.621s)
09:17:05     INFO -  787 INFO TEST-PASS | dom/media/test/test_seek-1.html | [started r11025_s16_c1.wav-0-seek1.js t=0.011] Length of array should match number of running tests
09:17:05     INFO -  788 INFO TEST-PASS | dom/media/test/test_seek-1.html | [started audio.wav-1-seek1.js t=0.012] Length of array should match number of running tests
09:17:05     INFO -  789 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: Should not be completed yet
09:17:05     INFO -  790 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: seeking should default to false
09:17:05     INFO -  791 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: seeking should be readonly
09:17:05     INFO -  792 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: Should not be completed yet
09:17:05     INFO -  793 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: seeking should default to false
09:17:05     INFO -  794 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: seeking should be readonly
09:17:05     INFO -  795 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: should not be completed yet
09:17:05     INFO -  796 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: Video currentTime should be around 0.0156235: 0.015624 (seeking)
09:17:05     INFO -  797 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: shuld not be completed yet
09:17:05     INFO -  798 INFO TEST-PASS | dom/media/test/test_seek-1.html | audio.wav seek test 1: Video currentTime should be around 0.0156235: 0.015624 (seeked)
09:17:05     INFO -  799 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: should not be completed yet
09:17:05     INFO -  800 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: Video currentTime should be around 0.5: 0.5 (seeking)
09:17:05     INFO -  801 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: shuld not be completed yet
09:17:05     INFO -  802 INFO TEST-PASS | dom/media/test/test_seek-1.html | r11025_s16_c1.wav seek test 1: Video currentTime should be around 0.5: 0.5 (seeked)
09:17:05     INFO -  Buffered messages finished
09:17:05    ERROR -  803 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_seek-1.html | Test timed out!
09:17:05     INFO -      onTimeout@dom/media/test/manifest.js:1717:7
09:17:05     INFO -      setTimeout handler*MediaTestManager/this.started@dom/media/test/manifest.js:1724:26
09:17:05     INFO -      startTest@dom/media/test/seek_support.js:26:3
09:17:05     INFO -      MediaTestManager/this.nextTest@dom/media/test/manifest.js:1773:7
09:17:05     INFO -      MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1693:7
09:17:05     INFO -  804 INFO r11025_s16_c1.wav-0-seek1.js timed out!
09:17:05     INFO -  Not taking screenshot here: see the one that was previously logged
09:17:05    ERROR -  805 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_seek-1.html | Test timed out!
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There are 31 failures associated to this bug in the last 7 days. These are occurring on linux64-qr, debug and opt builds.

:drno can you take a look at this?

Flags: needinfo?(drno)
Whiteboard: [stockwell needswork]

There is no recent activity on this bug, so I created this patch to disable the test.
In the last 21 days there are 73 failures and in the last 7 days 39 failures, mostly on linux64-qr.

Attachment #9036866 - Flags: review?(jmaher)

Comment on attachment 9036866 [details] [diff] [review]
Skipped test on linux qr

lets give :drno a few days to respond, the rate is getting close to where we should disable.

Attachment #9036866 - Flags: review?(jmaher)

Alastor, is this something you could have a look at on the side? I'd like to keep having this test, it's quite important for a number of application that seamless looping is working well.

Flags: needinfo?(alwu)

Sure, I'll take a look later, keep NI.

Assignee: nobody → alwu
Flags: needinfo?(alwu)

To make it output more debug information which is helpful to debug intermittent fail and refactor the test flow.

Alastor, can this be landed?

Flags: needinfo?(alwu)

Yes, I think we can land it now. I'm pushing my patches to try server again, but it haven't finish all the tests yet (and I don't why some of tasks are canceled)

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a64b9c11a0e75becffca55a88a03577b3f2c4ba&selectedJob=222756019

Flags: needinfo?(drno)
Flags: needinfo?(alwu)

Alastor it's due to bug 1521171. Trees are closed at the moment.

Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f421de9f952f
refactor seamless-looping test. r=padenot
Status: REOPENED → RESOLVED
Closed: Last year8 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla66
You need to log in before you can comment on or make changes to this bug.