Closed Bug 1344391 Opened 9 years ago Closed 1 year ago

Intermittent test_reset_src.html | Test timed out.

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Platform:
x86_64
Windows 10
Type:
enhancement

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: aryx, Unassigned)

References

(Depends on 1 open bug)

Details

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

Attachments

(1 file)

Bug 1344391 - Call play() only in dataloaded handler + count timeupdate events. r?alwu
47 bytes, text/x-phabricator-request
Details | Review
+++ This bug was initially created as a clone of Bug #1208273 +++ https://treeherder.mozilla.org/logviewer.html#?job_id=81558525&repo=mozilla-inbound 13:26:23 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: Trying to draw to a canvas should throw, since we don't have a frame anymore 13:26:23 INFO - [finished split.webm-8] remaining= bug516323.indexed.ogv-7 13:26:23 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished split.webm-8 t=5.684] Length of array should match number of running tests 13:26:23 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [started gizmo.mp4-9 t=5.684] Length of array should match number of running tests 13:26:23 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoHeight. 13:26:23 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoWidth. 13:26:23 INFO - Buffered messages finished 13:26:23 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_reset_src.html | Test timed out. 13:26:23 INFO - reportError@SimpleTest/TestRunner.js:120:7 13:26:23 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:141:7 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:162:5 13:26:23 INFO - TestRunner.runTests@SimpleTest/TestRunner.js:379:5 13:26:23 INFO - RunSet.runtests@SimpleTest/setup.js:190:3 13:26:23 INFO - RunSet.runall@SimpleTest/setup.js:169:5 13:26:23 INFO - hookupTests@SimpleTest/setup.js:262:5 13:26:23 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5 13:26:23 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11 13:26:23 INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3 13:26:23 INFO - hookup@SimpleTest/setup.js:242:5 13:26:23 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ccltbld%5Cappdata%5Clocal%5Ctemp:11:1 13:26:24 INFO - Test timed out. Remaining tests=bug516323.indexed.ogv-7,gizmo.mp4-9
(In reply to OrangeFactor Robot from comment #2) > 15 failures in 947 pushes (0.016 failures/push) were associated with this > bug in the last 7 days. > > Repository breakdown: > * mozilla-inbound: 7 > * autoland: 7 > * mozilla-central: 1 > > Platform breakdown: > * windows10-64-stylo-disabled: 8 > * windows10-64: 7 > > For more details, see: > https://brasstacks.mozilla.com/orangefactor/ > ?display=Bug&bugid=1344391&startday=2017-10-09&endday=2017-10-15&tree=all Windows 10 timeout.
Depends on: 1407553
OS: Unspecified → Windows 10
Hardware: Unspecified → x86_64
There are 27 total failures in the last 7 days, all on win10. Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=200965911&repo=mozilla-central&lineNumber=7280 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug516323.indexed.ogv: We should have a videoHeight. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug516323.indexed.ogv: We should have a videoWidth. 11:51:08 INFO - Buffered messages logged at 11:48:12 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozPaintedFrames should be positive or zero, is 0. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozFrameDelay should be positive or zero, is 0. 11:51:08 INFO - Buffered messages logged at 11:48:13 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: We should have a videoHeight. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: We should have a videoWidth. 11:51:08 INFO - Buffered messages logged at 11:48:15 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozPaintedFrames should be positive or zero, is 0. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozFrameDelay should be positive or zero, is 0. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: videoHeight should be zero when there is no video. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: videoWidth should be zero when there is no video. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozPaintedFrames should be zero when there is no video. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: mozFrameDelay should be zero when there is no video. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: Trying to draw to a canvas should throw, since we don't have a frame anymore 11:51:08 INFO - [finished split.webm-8] remaining= bug516323.indexed.ogv-7 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished split.webm-8 t=19.554] Length of array should match number of running tests 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [started gizmo.mp4-9 t=19.567] Length of array should match number of running tests 11:51:08 INFO - Buffered messages logged at 11:48:18 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoHeight. 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoWidth. 11:51:08 INFO - Buffered messages finished 11:51:08 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_reset_src.html | Test timed out! 11:51:08 INFO - onTimeout@dom/media/test/manifest.js:1777:7 11:51:08 INFO - setTimeout handler*MediaTestManager/this.started@dom/media/test/manifest.js:1784:26 11:51:08 INFO - startTest@dom/media/test/test_reset_src.html:91:3 11:51:08 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:08 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:08 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:08 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:08 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:08 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:08 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:08 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:08 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:08 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:08 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:08 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:08 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:08 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:08 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:08 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:08 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:08 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:08 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:08 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:08 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:08 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:08 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1753:7 11:51:08 INFO - bug516323.indexed.ogv-7 timed out! 11:51:08 INFO - GECKO(4776) | MediaDecoder=2ce3c75f400: channels=1 rate=44100 hasAudio=1 hasVideo=1 mPlayState=PLAYING 11:51:08 INFO - GECKO(4776) | ChannelMediaResource: mStreamLength=162193 mChannelOffset=162193 mCacheSuspended=0 mChannelEnded=1 mLoadID=2 11:51:08 INFO - GECKO(4776) | reader data: 11:51:08 INFO - GECKO(4776) | Container Type: application/ogg 11:51:08 INFO - GECKO(4776) | Audio Decoder(audio/vorbis, 1 channels @ 44.1kHz): vorbis audio decoder 11:51:08 INFO - GECKO(4776) | Audio Frames Decoded: 173 11:51:08 INFO - GECKO(4776) | Audio State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=173 out=172 qs=1 pending=0 wfd=0 eos=0 ds=0 wfk=0 sid=4294967295 11:51:08 INFO - GECKO(4776) | Video Decoder(video/theora, 426x240 @ 24.00): theora video decoder 11:51:08 INFO - GECKO(4776) | Hardware Video Decoding: disabled 11:51:08 INFO - GECKO(4776) | Video Frames Decoded: 35 (skipped=0) 11:51:08 INFO - GECKO(4776) | Video State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=34 out=34 qs=0 pending:0 wfd=0 eos=0 ds=0 wfk=0 sid=4294967295 11:51:08 INFO - GECKO(4776) | MDSM: duration=4208333 GetMediaTime=990000 GetClock=990000 mMediaSink=2ce381cf390 state=DECODING mPlayState=3 mSentFirstFrameLoadedEvent=1 IsPlaying=1 mAudioStatus=idle mVideoStatus=idle mDecodedAudioEndTime=2967800 mDecodedVideoEndTime=1416666 mAudioCompleted=0 mVideoCompleted=0 mIsPrerolling=0 11:51:08 INFO - GECKO(4776) | VideoSink: IsStarted=1 IsPlaying=1 VideoQueue(finished=0 size=11) mVideoFrameEndTime=1000000 mHasVideo=1 mVideoSinkEndRequest.Exists()=0 mEndPromiseHolder.IsEmpty()=0 11:51:08 INFO - GECKO(4776) | AudioSinkWrapper: IsStarted=1 IsPlaying=1 AudioEnded=0 11:51:08 INFO - GECKO(4776) | AudioSink: StartTime=0 LastGoodPosition=990000 Playing=1 OutputRate=44100 Written=48069 Errored=0 PlaybackComplete=0 11:51:08 INFO - [finished bug516323.indexed.ogv-7] remaining= gizmo.mp4-9 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished bug516323.indexed.ogv-7 t=192.339] Length of array should match number of running tests 11:51:08 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [started bug482461-theora.ogv-10 t=192.346] Length of array should match number of running tests 11:51:10 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: We should have a videoHeight. 11:51:10 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: We should have a videoWidth. 11:51:11 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozPaintedFrames should be positive or zero, is 0. 11:51:11 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozFrameDelay should be positive or zero, is 0. 11:51:13 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: We should have a videoHeight. 11:51:13 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: We should have a videoWidth. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozPaintedFrames should be positive or zero, is 0. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozFrameDelay should be positive or zero, is 0. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: videoHeight should be zero when there is no video. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: videoWidth should be zero when there is no video. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozPaintedFrames should be zero when there is no video. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: mozFrameDelay should be zero when there is no video. 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | bug482461-theora.ogv: Trying to draw to a canvas should throw, since we don't have a frame anymore 11:51:14 INFO - [finished bug482461-theora.ogv-10] remaining= gizmo.mp4-9 11:51:14 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished bug482461-theora.ogv-10 t=198.191] Length of array should match number of running tests 11:51:15 INFO - Not taking screenshot here: see the one that was previously logged 11:51:15 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_reset_src.html | Test timed out! 11:51:15 INFO - onTimeout@dom/media/test/manifest.js:1777:7 11:51:15 INFO - setTimeout handler*MediaTestManager/this.started@dom/media/test/manifest.js:1784:26 11:51:15 INFO - startTest@dom/media/test/test_reset_src.html:91:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:15 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:15 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:15 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:15 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:15 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:15 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:15 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:15 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:15 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:15 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:15 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:15 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:15 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:15 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:15 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:15 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:15 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:15 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:15 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:15 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1812:7 11:51:15 INFO - finish@dom/media/test/test_reset_src.html:26:3 11:51:15 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:5 11:51:15 INFO - EventListener.handleEvent*onTimeUpdate_Video@dom/media/test/test_reset_src.html:68:7 11:51:15 INFO - EventListener.handleEvent*onLoadedData_Video@dom/media/test/test_reset_src.html:78:3 11:51:15 INFO - EventListener.handleEvent*startTest@dom/media/test/test_reset_src.html:86:3 11:51:15 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1833:7 11:51:15 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1753:7 11:51:15 INFO - gizmo.mp4-9 timed out! Nils, can you work on this or assign it to someone?
Flags: needinfo?(drno)

There are 15 total failures in the last 7 days on

  • windows10-64 asan
  • windows10-64-devedition opt
  • windows10-64-qr debug
  • windows10-64-shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=289270657&repo=autoland&lineNumber=3085[task 2020-02-17T20:50:46.083Z] 20:50:46 INFO - TEST-START | dom/media/test/test_reset_src.html
[task 2020-02-17T20:53:49.628Z] 20:53:49 INFO - TEST-INFO | started process screenshot
[task 2020-02-17T20:53:49.691Z] 20:53:49 INFO - TEST-INFO | screenshot: exit 0
[task 2020-02-17T20:53:49.691Z] 20:53:49 INFO - <snipped 41 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-02-17T20:53:49.691Z] 20:53:49 INFO - Buffered messages logged at 20:50:46
[task 2020-02-17T20:53:49.692Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozPaintedFrames should be positive or zero, is 6.
[task 2020-02-17T20:53:49.692Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozFrameDelay should be positive or zero, is 0.010145862393125383.
[task 2020-02-17T20:53:49.693Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: We should have a videoHeight.
[task 2020-02-17T20:53:49.693Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: We should have a videoWidth.
[task 2020-02-17T20:53:49.694Z] 20:53:49 INFO - Buffered messages logged at 20:50:47
[task 2020-02-17T20:53:49.695Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo-short.mp4: mozPaintedFrames should be positive or zero, is 0.
[task 2020-02-17T20:53:49.695Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo-short.mp4: mozFrameDelay should be positive or zero, is 0.
[task 2020-02-17T20:53:49.695Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo-short.mp4: We should have a videoHeight.
[task 2020-02-17T20:53:49.696Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo-short.mp4: We should have a videoWidth.
[task 2020-02-17T20:53:49.696Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozPaintedFrames should be positive or zero, is 6.
[task 2020-02-17T20:53:49.696Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozFrameDelay should be positive or zero, is 0.003981220797615339.
[task 2020-02-17T20:53:49.697Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: videoHeight should be zero when there is no video.
[task 2020-02-17T20:53:49.697Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: videoWidth should be zero when there is no video.
[task 2020-02-17T20:53:49.698Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozPaintedFrames should be zero when there is no video.
[task 2020-02-17T20:53:49.698Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: mozFrameDelay should be zero when there is no video.
[task 2020-02-17T20:53:49.698Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | vp9-short.webm: Trying to draw to a canvas should throw, since we don't have a frame anymore
[task 2020-02-17T20:53:49.699Z] 20:53:49 INFO - [finished vp9-short.webm-2] remaining= gizmo-short.mp4-3

[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | split.webm: Trying to draw to a canvas should throw, since we don't have a frame anymore
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - [finished split.webm-8] remaining= bug516323.indexed.ogv-7
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished split.webm-8 t=5.33] Length of array should match number of running tests
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [started gizmo.mp4-9 t=5.332] Length of array should match number of running tests
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoHeight.
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | gizmo.mp4: We should have a videoWidth.
[task 2020-02-17T20:53:49.727Z] 20:53:49 INFO - Buffered messages finished
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_reset_src.html | Test timed out!
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - onTimeout@dom/media/test/manifest.js:2088:9
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - setTimeout handlerMediaTestManager/this.started@dom/media/test/manifest.js:2095:57
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - startTest@dom/media/test/test_reset_src.html:92:11
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:2169:12
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:2141:12
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - finish@dom/media/test/test_reset_src.html:26:11
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:11
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - EventListener.handleEventonTimeUpdate_Video@dom/media/test/test_reset_src.html:69:9
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - EventListener.handleEventonLoadedData_Video@dom/media/test/test_reset_src.html:79:5
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - EventListener.handleEventstartTest@dom/media/test/test_reset_src.html:87:5
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:2169:12
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:2141:12
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - finish@dom/media/test/test_reset_src.html:26:11
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:11
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - EventListener.handleEventonTimeUpdate_Video@dom/media/test/test_reset_src.html:69:9
[task 2020-02-17T20:53:49.728Z] 20:53:49 INFO - EventListener.handleEventonLoadedData_Video@dom/media/test/test_reset_src.html:79:5
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - EventListener.handleEventstartTest@dom/media/test/test_reset_src.html:87:5
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:2169:12
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:2141:12
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - finish@dom/media/test/test_reset_src.html:26:11
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - onLoadedData_Audio@dom/media/test/test_reset_src.html:40:11
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - EventListener.handleEventonTimeUpdate_Video@dom/media/test/test_reset_src.html:69:9
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - EventListener.handleEventonLoadedData_Video@dom/media/test/test_reset_src.html:79:5
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - EventListener.handleEventstartTest@dom/media/test/test_reset_src.html:87:5
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:2169:12
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:2064:12
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - Async*MediaTestManager/this.runTests@dom/media/test/manifest.js:2063:19
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - @dom/media/test/test_reset_src.html:95:9
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - bug516323.indexed.ogv-7 timed out!
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"PLAYING","channels":1,"containerType":"application/ogg","hasAudio":true,"hasVideo":true,"instance":"22e04871000","rate":44100,"reader":{"audioChannels":1,"audioDecoderName":"vorbis audio decoder (remote)","audioFramesDecoded":173,"audioRate":44.099998474121094,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":173,"numSamplesOutput":172,"pending":0,"queueSize":1,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/vorbis","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"theora video decoder","videoHardwareAccelerated":false,"videoHeight":240,"videoNumSamplesOutputTotal":35,"videoNumSamplesSkippedTotal":0,"videoRate":24.000383377075195,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":34,"numSamplesOutput":34,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/theora","videoWidth":426},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":990000,"decodedAudioEndTime":2967800,"decodedVideoEndTime":1416666,"duration":4208333,"isPlaying":true,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":true,"isStarted":false,"lastGoodPosition":990000,"outputRate":44100,"playbackComplete":false,"startTime":0,"written":48069},"isPlaying":true,"isStarted":true},"decodedStream":{"audioQueueFinished":false,"audioQueueSize":0,"data":{"audioFramesWritten":0,"haveSentFinishAudio":false,"haveSentFinishVideo":false,"instance":"","lastVideoEndTime":0,"lastVideoStartTime":0,"nextAudioTime":0,"streamAudioWritten":0,"streamVideoWritten":0},"instance":"","lastAudio":0,"lastOutputTime":0,"playing":0,"startTime":0},"videoSink":{"endPromiseHolderIsEmpty":false,"finished":false,"hasVideo":true,"isPlaying":true,"isStarted":true,"size":11,"videoFrameEndTime":1000000,"videoSinkEndRequestExists":false}},"mediaTime":990000,"playState":3,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"idle"}}}
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - [finished bug516323.indexed.ogv-7] remaining= gizmo.mp4-9
[task 2020-02-17T20:53:49.729Z] 20:53:49 INFO - TEST-PASS | dom/media/test/test_reset_src.html | [finished bug516323.indexed.ogv-7 t=183.502] Length of array should match number of running tests

Failure rate in the last 7 days in not concerning, however this seems to be a persistent issue based on failure history: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-02-10&endday=2020-02-17&tree=all&bug=1344391

Bryce can you assign someone to take a look?

Flags: needinfo?(bvandyk)
Whiteboard: [stockwell needswork:owner]

The tests look to be reliably failing around gizmo.mp4[0]. We're hitting the loadeddata[1] code, but then we're seemingly not hitting the timeupdate[2] case. It's not clear to me why the gizmo case is problematic. I don't know if it will help, but I don't see that we need to call play() in our start test function -- in my testing this will mean that loadeddata and the first timeupdate will race. loadeddata will normally win in local testing, but since the test is being problematic it can't hurt to make it more deterministic.

[0] https://searchfox.org/mozilla-central/rev/23c25cd32a1e87095301273937b4ee162f41e860/dom/media/test/manifest.js#843
[1] https://searchfox.org/mozilla-central/rev/23c25cd32a1e87095301273937b4ee162f41e860/dom/media/test/test_reset_src.html#75
[2] https://searchfox.org/mozilla-central/rev/23c25cd32a1e87095301273937b4ee162f41e860/dom/media/test/test_reset_src.html#47

Flags: needinfo?(drno)
Keywords: leave-open

Calling play after dataloaded ensures dataloaded and timeupdate event will not
race. It's not clear if this is the root cause of intermittent test issues, but
it does not hurt to make the test more deterministic. It also makes the test
clearer in my opinion, as having two invocations of play isn't needed.

Also add a couple of drive by style fix ups.

Attachment #9193281 - Attachment description: Bug 1344391 - Call play() only in dataloaded handler. r?alwu → Bug 1344391 - Call play() only in dataloaded handler + count timeupdate events. r?alwu
Severity: normal → S4
Flags: needinfo?(bvandyk)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: