1295884 - Intermittent dom/media/test/test_background_video_suspend_ends.html | Test timed out.

It appears that gizmo-noaudio test starts playing, is marked as hidden, but the event is never received. This results in the test waiting for the event and timing out.

Comment hidden (mozreview-request)

u480271

Updated

•

8 years ago

Attachment #8784656 - Flags: review?(jwwang)

u480271

Updated

•

8 years ago

Attachment #8784656 - Attachment is obsolete: true

u480271

Comment 4

•

8 years ago

I think this might be a duplicate of bug 1297429

Depends on: 1297429

Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)

Updated

•

8 years ago

Priority: -- → P5

Comment hidden (Intermittent Failures Robot)

Geoff Brown [:gbrown]

Comment 7

•

8 years ago

This started failing again on Jan 18; I wonder why. Recent logs seem to end something like: 12:06:04 INFO - Buffered messages logged at 12:01:07 12:06:04 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | gizmo-noaudio.webm-3 ended 12:06:04 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | current time approximates duration. 12:06:04 INFO - [finished gizmo-noaudio.webm-3] remaining= gizmo-noaudio.mp4-1 12:06:04 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [finished gizmo-noaudio.webm-3 t=17.495] Length of array should match number of running tests 12:06:04 INFO - Buffered messages finished before timing out.

Comment hidden (Intermittent Failures Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 10

•

8 years ago

https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=74495313&lineNumber=2900 [finished gizmo.webm-2] remaining= gizmo-noaudio.webm-3 gizmo-noaudio.webm is not finished. WARNING: Decoder=d05efa60 channels=0 rate=0 hasAudio=0 hasVideo=1 mPlayState=PLAYING mdsm=d63b2800 reader data: audio decoder: unavailable audio frames decoded: 0 video decoder: shutdown hardware video decoding: disabled video frames decoded: 40 (skipped:0) video state: ni=1 no=1 ie=0 demuxr:0 demuxq:0 tt:-1.000000 tths:-1 in:0 out:0 qs=0 pending:0 waiting:0 wfk:0, sid:4294967295 [1605] WARNING: Decoder=d05efa60 GetMediaTime=1333000 GetClock=310656666 mMediaSink=da315ee0 state=DECODING mPlayState=3 mSentFirstFrameLoadedEvent=1 IsPlaying=1 mAudioStatus=idle mVideoStatus=pending mDecodedAudioEndTime=0 mDecodedVideoEndTime=1333000 mAudioCompleted=0 mVideoCompleted=0 mIsPrerolling=0 IsStarted=1 IsPlaying=1, VideoQueue: finished=0 size=1, mVideoFrameEndTime=1333000 mHasVideo=1 mVideoSinkEndRequest.Exists()=0 mEndPromiseHolder.IsEmpty()=0 mVideoStatus=pending means video request is not resolved. It looks like something wrong to the WEBM decoder.

Flags: needinfo?(jyavenard)

Jean-Yves Avenard [:jya]

Comment 11

•

8 years ago

can't comment on that particular version. now that bug 1319987 has landed, let see how that pans out now.

Flags: needinfo?(jyavenard)

Comment hidden (Intermittent Failures Robot)

JW Wang [:jwwang] [:jw_wang]

Updated

•

8 years ago

Depends on: 1339351

Joel Maher ( :jmaher ) (UTC -8)

Comment 13

•

8 years ago

this looks fixed :)

Whiteboard: [stockwell fixed]

Comment hidden (Intermittent Failures Robot)

Emma Humphries ☕️🎸🧞‍♀️✨ (she/they) [:emceeaich] (Pacific Time) use needinfo

Updated

•

7 years ago

Status: NEW → RESOLVED

Closed: 7 years ago

Keywords: bulk-close-intermittents

Resolution: --- → INCOMPLETE

Phil Ringnalda (:philor)

Updated

•

7 years ago

Status: RESOLVED → REOPENED

Resolution: INCOMPLETE → ---

Comment hidden (Intermittent Failures Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 17

•

7 years ago

(In reply to OrangeFactor Robot from comment #16) > 5 failures in 947 pushes (0.005 failures/push) were associated with this bug > in the last 7 days. > > Repository breakdown: > * mozilla-inbound: 3 > * autoland: 2 > > Platform breakdown: > * windows10-64: 5 > > For more details, see: > https://brasstacks.mozilla.com/orangefactor/ > ?display=Bug&bugid=1295884&startday=2017-10-09&endday=2017-10-15&tree=all Windows 10 timeout.

Depends on: 1407553

OS: Unspecified → Windows 10

Hardware: Unspecified → x86_64

Comment hidden (Intermittent Failures Robot)

u480271

Updated

•

7 years ago

Depends on: 1440555

Comment hidden (Intermittent Failures Robot)

u480271

Updated

•

7 years ago

Depends on: 1451221

Comment hidden (Intermittent Failures Robot)

u480271

Comment 49

•

6 years ago

I'm out of ideas as to why this test keeps failing. Does this log say that the MDSM still considers it playing but mVideoStatus=idle and there are 11 frames in the queue? 18:27:55 INFO - 192 INFO TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo.mp4-0 t=0.007] Length of array should match number of running tests 18:27:55 INFO - 193 INFO [18:24:55.211] gizmo.mp4-0 Start playing 18:27:55 INFO - 194 INFO [18:24:55.211] gizmo.mp4-0 Set hidden 18:27:55 INFO - 195 INFO [18:24:55.211] gizmo.mp4-0 Waiting for video suspend 18:27:55 INFO - Buffered messages logged at 18:24:56 18:27:55 INFO - 196 INFO [18:24:56.280] gizmo.mp4-0 Waiting for ended 18:27:55 INFO - Buffered messages finished 18:27:55 ERROR - 197 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_background_video_suspend_ends.html | Test timed out! 18:27:55 INFO - onTimeout@dom/media/test/manifest.js:1717:7 18:27:55 INFO - setTimeout handler*MediaTestManager/this.started@dom/media/test/manifest.js:1724:26 18:27:55 INFO - runTest@dom/media/test/test_background_video_suspend_ends.html:17:5 18:27:55 INFO - async*MediaTestManager/this.nextTest@dom/media/test/manifest.js:1773:7 18:27:55 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1693:7 18:27:55 INFO - 198 INFO gizmo.mp4-0 timed out! 18:27:55 INFO - GECKO(6688) | MediaDecoder=19272451400: channels=1 rate=48000 hasAudio=1 hasVideo=1 mPlayState=PLAYING 18:27:55 INFO - GECKO(6688) | ChannelMediaResource: mStreamLength=455255 mChannelOffset=455255 mCacheSuspended=0 mChannelEnded=1 mLoadID=1 18:27:55 INFO - GECKO(6688) | reader data: 18:27:55 INFO - GECKO(6688) | Container Type: video/mp4 18:27:55 INFO - GECKO(6688) | Audio Decoder(audio/mp4a-latm, 1 channels @ 48.0kHz): wmf audio decoder 18:27:55 INFO - GECKO(6688) | Audio Frames Decoded: 262 18:27:55 INFO - GECKO(6688) | Audio State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=262 out=262 qs=0 pending=0 wfd=0 eos=1 ds=0 wfk=0 sid=4294967295 18:27:55 INFO - GECKO(6688) | Video Decoder(video/avc, 560x320 @ 30.00): blank media data decoder 18:27:55 INFO - GECKO(6688) | Hardware Video Decoding: disabled 18:27:55 INFO - GECKO(6688) | Video Frames Decoded: 145 (skipped=0) 18:27:55 INFO - GECKO(6688) | Video State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=111 out=111 qs=2 pending:2 wfd=0 eos=1 ds=3 wfk=0 sid=4294967295 18:27:55 INFO - GECKO(6688) | MDSM: duration=5589333 GetMediaTime=5100000 GetClock=5100000 mMediaSink=19272433cc0 state=DECODING mPlayState=3 mSentFirstFrameLoadedEvent=1 IsPlaying=1 mAudioStatus=idle mVideoStatus=idle mDecodedAudioEndTime=5589333 mDecodedVideoEndTime=5466666 mAudioCompleted=0 mVideoCompleted=0 mIsPrerolling=0 18:27:55 INFO - GECKO(6688) | VideoSink: IsStarted=1 IsPlaying=1 VideoQueue(finished=0 size=11) mVideoFrameEndTime=5133333 mHasVideo=1 mVideoSinkEndRequest.Exists()=0 mEndPromiseHolder.IsEmpty()=0 18:27:55 INFO - GECKO(6688) | AudioSinkWrapper: IsStarted=1 IsPlaying=1 AudioEnded=0 18:27:55 INFO - GECKO(6688) | AudioSink: StartTime=0 LastGoodPosition=5100000 Playing=1 OutputRate=48000 Written=249600 Errored=0 PlaybackComplete=0

Flags: needinfo?(cpearce)

Comment hidden (Intermittent Failures Robot)

Chris Pearce [:cpearce (Not reading bugmail)]

Comment 56

•

6 years ago

(In reply to Dan Glastonbury (:kamidphish) | needinfo me from comment #49) > I'm out of ideas as to why this test keeps failing. Does this log say that > the MDSM still considers it playing but mVideoStatus=idle and there are 11 > frames in the queue? > > 18:27:55 INFO - 192 INFO TEST-PASS | > dom/media/test/test_background_video_suspend_ends.html | [started > gizmo.mp4-0 t=0.007] Length of array should match number of running tests > 18:27:55 INFO - 193 INFO [18:24:55.211] gizmo.mp4-0 Start playing > 18:27:55 INFO - 194 INFO [18:24:55.211] gizmo.mp4-0 Set hidden > 18:27:55 INFO - 195 INFO [18:24:55.211] gizmo.mp4-0 Waiting for video > suspend > 18:27:55 INFO - Buffered messages logged at 18:24:56 > 18:27:55 INFO - 196 INFO [18:24:56.280] gizmo.mp4-0 Waiting for ended > 18:27:55 INFO - Buffered messages finished > 18:27:55 ERROR - 197 INFO TEST-UNEXPECTED-FAIL | > dom/media/test/test_background_video_suspend_ends.html | Test timed out! > 18:27:55 INFO - onTimeout@dom/media/test/manifest.js:1717:7 > 18:27:55 INFO - setTimeout > handler*MediaTestManager/this.started@dom/media/test/manifest.js:1724:26 > 18:27:55 INFO - > runTest@dom/media/test/test_background_video_suspend_ends.html:17:5 > 18:27:55 INFO - > async*MediaTestManager/this.nextTest@dom/media/test/manifest.js:1773:7 > 18:27:55 INFO - > MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1693:7 > 18:27:55 INFO - 198 INFO gizmo.mp4-0 timed out! > 18:27:55 INFO - GECKO(6688) | MediaDecoder=19272451400: channels=1 > rate=48000 hasAudio=1 hasVideo=1 mPlayState=PLAYING > 18:27:55 INFO - GECKO(6688) | ChannelMediaResource: > mStreamLength=455255 mChannelOffset=455255 mCacheSuspended=0 mChannelEnded=1 > mLoadID=1 > 18:27:55 INFO - GECKO(6688) | reader data: > 18:27:55 INFO - GECKO(6688) | Container Type: video/mp4 > 18:27:55 INFO - GECKO(6688) | Audio Decoder(audio/mp4a-latm, 1 channels > @ 48.0kHz): wmf audio decoder > 18:27:55 INFO - GECKO(6688) | Audio Frames Decoded: 262 > 18:27:55 INFO - GECKO(6688) | Audio State: ni=0 no=0 wp=0 demuxr=0 > demuxq=0 decoder=0 tt=-1.0 tths=-1 in=262 out=262 qs=0 pending=0 wfd=0 eos=1 > ds=0 wfk=0 sid=4294967295 > 18:27:55 INFO - GECKO(6688) | Video Decoder(video/avc, 560x320 @ > 30.00): blank media data decoder > 18:27:55 INFO - GECKO(6688) | Hardware Video Decoding: disabled > 18:27:55 INFO - GECKO(6688) | Video Frames Decoded: 145 (skipped=0) > 18:27:55 INFO - GECKO(6688) | Video State: ni=0 no=0 wp=0 demuxr=0 > demuxq=0 decoder=0 tt=-1.0 tths=-1 in=111 out=111 qs=2 pending:2 wfd=0 eos=1 > ds=3 wfk=0 sid=4294967295 > 18:27:55 INFO - GECKO(6688) | MDSM: duration=5589333 > GetMediaTime=5100000 GetClock=5100000 mMediaSink=19272433cc0 state=DECODING > mPlayState=3 mSentFirstFrameLoadedEvent=1 IsPlaying=1 mAudioStatus=idle > mVideoStatus=idle mDecodedAudioEndTime=5589333 mDecodedVideoEndTime=5466666 > mAudioCompleted=0 mVideoCompleted=0 mIsPrerolling=0 > 18:27:55 INFO - GECKO(6688) | VideoSink: IsStarted=1 IsPlaying=1 > VideoQueue(finished=0 size=11) mVideoFrameEndTime=5133333 mHasVideo=1 > mVideoSinkEndRequest.Exists()=0 mEndPromiseHolder.IsEmpty()=0 > 18:27:55 INFO - GECKO(6688) | AudioSinkWrapper: IsStarted=1 IsPlaying=1 > AudioEnded=0 > 18:27:55 INFO - GECKO(6688) | AudioSink: StartTime=0 > LastGoodPosition=5100000 Playing=1 OutputRate=48000 Written=249600 > Errored=0 PlaybackComplete=0 I'll let someone on the media team handle this... deferring to jya for prioritization...

Flags: needinfo?(cpearce) → needinfo?(jyavenard)

Chris Pearce [:cpearce (Not reading bugmail)]

Updated

•

6 years ago

Assignee: dglastonbury → nobody

Comment hidden (Intermittent Failures Robot)

Jean-Yves Avenard [:jya]

Comment 58

•

6 years ago

must be an event race in there... not enough bandwidth to look into this at the moment

Flags: needinfo?(jyavenard)

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 91

•

6 years ago

There are 22 total failures in the last 7 days on windows10 all build types

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231684821&repo=autoland&lineNumber=1696

18:04:31 INFO - TEST-START | dom/media/test/test_background_video_suspend_ends.html
18:07:40 INFO - TEST-INFO | started process screenshot
18:07:40 INFO - TEST-INFO | screenshot: exit 0
18:07:40 INFO - Buffered messages logged at 18:04:31
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | A valid string reason is expected
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | Reason cannot be empty
18:07:40 INFO - Buffered messages logged at 18:04:32
18:07:40 INFO - Test Background Suspended Video Fires 'ended' Event
18:07:40 INFO - Started Mon Mar 04 2019 18:04:32 GMT+0000 (Greenwich Mean Time) (1551722672.027s)
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo.mp4-0 t=0.01] Length of array should match number of running tests
18:07:40 INFO - [18:04:32.39] gizmo.mp4-0 Start playing
18:07:40 INFO - [18:04:32.39] gizmo.mp4-0 Set hidden
18:07:40 INFO - [18:04:32.39] gizmo.mp4-0 Waiting for video suspend
18:07:40 INFO - Buffered messages logged at 18:04:33
18:07:40 INFO - [18:04:33.207] gizmo.mp4-0 Waiting for ended
18:07:40 INFO - Buffered messages logged at 18:04:34
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | current time approximates duration.
18:07:40 INFO - [finished gizmo.mp4-0] remaining=
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [finished gizmo.mp4-0 t=2.332] Length of array should match number of running tests
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo-noaudio.mp4-1 t=2.334] Length of array should match number of running tests
18:07:40 INFO - [18:04:34.361] gizmo-noaudio.mp4-1 Start playing
18:07:40 INFO - [18:04:34.362] gizmo-noaudio.mp4-1 Set hidden
18:07:40 INFO - [18:04:34.362] gizmo-noaudio.mp4-1 Waiting for video suspend
18:07:40 INFO - Buffered messages logged at 18:04:35
18:07:40 INFO - [18:04:35.526] gizmo-noaudio.mp4-1 Waiting for ended
18:07:40 INFO - Buffered messages logged at 18:04:40
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | current time approximates duration.
18:07:40 INFO - [finished gizmo-noaudio.mp4-1] remaining=
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [finished gizmo-noaudio.mp4-1 t=8.155] Length of array should match number of running tests
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo.webm-2 t=8.157] Length of array should match number of running tests
18:07:40 INFO - [18:04:40.185] gizmo.webm-2 Start playing
18:07:40 INFO - [18:04:40.186] gizmo.webm-2 Set hidden
18:07:40 INFO - [18:04:40.186] gizmo.webm-2 Waiting for video suspend
18:07:40 INFO - Buffered messages logged at 18:04:41
18:07:40 INFO - [18:04:41.271] gizmo.webm-2 Waiting for ended
18:07:40 INFO - Buffered messages finished
18:07:40 INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_background_video_suspend_ends.html | Test timed out!
18:07:40 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
18:07:40 INFO - onTimeout@dom/media/test/manifest.js:1778:7
18:07:40 INFO - setTimeout handler*MediaTestManager/this.started@dom/media/test/manifest.js:1785:57

8:07:40 INFO - runTest@dom/media/test/test_background_video_suspend_ends.html:17:13
18:07:40 INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:1834:12
18:07:40 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1813:12
18:07:40 INFO - runTest@dom/media/test/test_background_video_suspend_ends.html:40:13
18:07:40 INFO - asyncMediaTestManager/this.nextTest@dom/media/test/manifest.js:1834:12
18:07:40 INFO - MediaTestManager/this.finished@dom/media/test/manifest.js:1813:12
18:07:40 INFO - runTest@dom/media/test/test_background_video_suspend_ends.html:40:13
18:07:40 INFO - asyncMediaTestManager/this.nextTest@dom/media/test/manifest.js:1834:12
18:07:40 INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:1754:12
18:07:40 INFO - gizmo.webm-2 timed out!
18:07:40 INFO - GECKO(9296) | MediaDecoder=130c16ab4680: channels=1 rate=48000 hasAudio=1 hasVideo=1 mPlayState=PLAYING
18:07:40 INFO - GECKO(9296) | ChannelMediaResource: mStreamLength=159035 mChannelOffset=159035 mCacheSuspended=0 mChannelEnded=1 mLoadID=1
18:07:40 INFO - GECKO(9296) | reader data:
18:07:40 INFO - GECKO(9296) | Container Type: video/webm
18:07:40 INFO - GECKO(9296) | Audio Decoder(audio/opus, 1 channels @ 48.0kHz): opus audio decoder
18:07:40 INFO - GECKO(9296) | Audio Frames Decoded: 279
18:07:40 INFO - GECKO(9296) | Audio State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=279 out=279 qs=0 pending=0 wfd=0 eos=1 ds=0 wfk=0 sid=4294967295
18:07:40 INFO - GECKO(9296) | Video Decoder(video/vp9, 0x0 @ 30.01): blank media data decoder
18:07:40 INFO - GECKO(9296) | Hardware Video Decoding: disabled
18:07:40 INFO - GECKO(9296) | Video Frames Decoded: 132 (skipped=0)
18:07:40 INFO - GECKO(9296) | Video State: ni=0 no=0 wp=0 demuxr=0 demuxq=0 decoder=0 tt=-1.0 tths=-1 in=95 out=95 qs=0 pending:0 wfd=0 eos=0 ds=0 wfk=0 sid=4294967295
18:07:40 INFO - GECKO(9296) | MDSM: duration=5590000 GetMediaTime=4080020 GetClock=4080020 mMediaSink=130216b70800 state=DECODING mPlayState=3 mSentFirstFrameLoadedEvent=1 IsPlaying=1 mAudioStatus=idle mVideoStatus=idle mDecodedAudioEndTime=5583000 mDecodedVideoEndTime=4433000 mAudioCompleted=0 mVideoCompleted=0 mIsPrerolling=0
18:07:40 INFO - GECKO(9296) | VideoSink: IsStarted=1 IsPlaying=1 VideoQueue(finished=0 size=11) mVideoFrameEndTime=4100000 mHasVideo=1 mVideoSinkEndRequest.Exists()=0 mEndPromiseHolder.IsEmpty()=0
18:07:40 INFO - GECKO(9296) | AudioSinkWrapper: IsStarted=1 IsPlaying=1 AudioEnded=0
18:07:40 INFO - GECKO(9296) | AudioSink: StartTime=0 LastGoodPosition=4080020 Playing=1 OutputRate=48000 Written=200640 Errored=0 PlaybackComplete=0
18:07:40 INFO - [finished gizmo.webm-2] remaining=
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [finished gizmo.webm-2 t=188.212] Length of array should match number of running tests
18:07:40 INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo-noaudio.webm-3 t=188.215] Length of array should match number of running tests

Nils, can you take a look?

Flags: needinfo?(drno)

Andreea Pavel [:apavel]

Updated

•

6 years ago

Whiteboard: [stockwell fixed] → [stockwell fixed][stockwel:needsowner]

Comment hidden (Intermittent Failures Robot)

Razvan Maries

Comment 119

•

5 years ago

There are 24 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-08-27&endday=2019-09-03&tree=trunk&bug=1295884

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264715786&repo=autoland&lineNumber=1764

Flags: needinfo?(drno)

Razvan Maries

Comment 120

•

5 years ago

Randel, Nils's account is inactive. Could you take a look and assign this to someone?

Flags: needinfo?(rjesup)

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 129

•

5 years ago

There are 5 total failures in the last 7 days on windows10-64 opt and debug and one failure on windows10-64-shippable-qr opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=274309235&repo=autoland&lineNumber=5931

[task 2019-11-03T22:41:47.438Z] 22:41:47 [task 2019-11-03T22:41:47.457Z] 22:41:47 [task 2019-11-03T22:41:47.466Z] 22:41:47 [task 2019-11-03T22:41:47.497Z] 22:41:47 [task 2019-11-03T22:41:47.507Z] 22:41:47 [task 2019-11-03T22:41:47.507Z] 22:41:47 [task 2019-11-03T22:41:47.516Z] 22:41:47 [task 2019-11-03T22:42:47.765Z] 22:42:47 [task 2019-11-03T22:42:51.781Z] 22:42:51 [task 2019-11-03T22:42:51.781Z] 22:42:51 [task 2019-11-03T22:42:51.781Z] 22:42:51 [task 2019-11-03T22:43:11.174Z] 22:43:11 [task 2019-11-03T22:44:47.622Z] 22:44:47 [task 2019-11-03T22:44:47.704Z] 22:44:47 [task 2019-11-03T22:44:47.704Z] 22:44:47 [task 2019-11-03T22:44:47.704Z] 22:44:47 [task 2019-11-03T22:44:47.704Z] 22:44:47 [task 2019-11-03T22:44:47.705Z] 22:44:47 [task 2019-11-03T22:44:47.705Z] 22:44:47 [task 2019-11-03T22:44:47.705Z] 22:44:47 [task 2019-11-03T22:44:47.705Z] 22:44:47 [task 2019-11-03T22:44:47.705Z] 22:44:47 [task 2019-11-03T22:44:47.706Z] 22:44:47 [task 2019-11-03T22:44:47.706Z] 22:44:47 [task 2019-11-03T22:44:47.706Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.707Z] 22:44:47 [task 2019-11-03T22:44:47.708Z] 22:44:47 [task 2019-11-03T22:44:47.708Z] 22:44:47 [task 2019-11-03T22:44:47.708Z] 22:44:47 [task 2019-11-03T22:44:47.708Z] 22:44:47 [task 2019-11-03T22:44:47.708Z] 22:44:47 INFO - TEST-START | dom/media/test/test_background_video_suspend_ends.html
INFO - GECKO(6680) | [Parent 5472, Main Thread] WARNING: NS_ENSURE_TRUE(aCSP) failed: file z:/build/build/src/dom/security/FramingChecker.cpp, line 175
INFO - GECKO(6680) | ++DOMWINDOW == 10 (000001E4C6774000) [pid = 4920] [serial = 299] [outer = 000001E4C470D880]
INFO - GECKO(6680) | --DOCSHELL 000001E4C7217000 == 3 [pid = 4920] [id = {ccf8804c-ed50-4010-9210-07ee560c3e8e}] [url = about:blank]
INFO - GECKO(6680) | ++DOCSHELL 000001E4BE858800 == 4 [pid = 4920] [id = {bc2eed1b-3001-4e44-8d95-6219334d7564}]
INFO - GECKO(6680) | ++DOMWINDOW == 11 (000001E4C8F2FF20) [pid = 4920] [serial = 300] [outer = 0000000000000000]
INFO - GECKO(6680) | ++DOMWINDOW == 12 (000001E4C7096800) [pid = 4920] [serial = 301] [outer = 000001E4C8F2FF20]
INFO - GECKO(6680) | --DOMWINDOW == 11 (000001E4C8F2FD40) [pid = 4920] [serial = 296] [outer = 0000000000000000] [url = about:blank]
INFO - GECKO(6680) | --DOMWINDOW == 10 (000001E4C4775400) [pid = 4920] [serial = 298] [outer = 0000000000000000] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
INFO - GECKO(6680) | --DOMWINDOW == 9 (000001E4C8CAB800) [pid = 4920] [serial = 295] [outer = 0000000000000000] [url = http://mochi.test:8888/tests/dom/media/test/test_background_video_suspend.html]
INFO - GECKO(6680) | --DOMWINDOW == 8 (000001E4C8F6C000) [pid = 4920] [serial = 297] [outer = 0000000000000000] [url = about:blank]
INFO - GECKO(6680) | [Parent 5472, Jump List] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/widget/windows/WinUtils.cpp, line 1346
INFO - TEST-INFO | started process screenshot
INFO - TEST-INFO | screenshot: exit 0
INFO - Buffered messages logged at 22:41:47
INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | A valid string reason is expected
INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | Reason cannot be empty
INFO - Test Background Suspended Video Fires 'ended' Event
INFO - Started Sun Nov 03 2019 22:41:47 GMT+0000 (Greenwich Mean Time) (1572820907.544s)
INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo.mp4-0 t=0.011] Length of array should match number of running tests
INFO - [22:41:47.556] gizmo.mp4-0 Start playing
INFO - [22:41:47.557] gizmo.mp4-0 Set hidden
INFO - [22:41:47.557] gizmo.mp4-0 Waiting for video suspend
INFO - Buffered messages logged at 22:41:48
INFO - [22:41:48.823] gizmo.mp4-0 Waiting for ended
INFO - Buffered messages finished
INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_background_video_suspend_ends.html | Test timed out!
INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
INFO - onTimeout@dom/media/test/manifest.js:2086:9
INFO - setTimeout handlerMediaTestManager/this.started@dom/media/test/manifest.js:2093:57
INFO - runTest@dom/media/test/test_background_video_suspend_ends.html:17:13
INFO - MediaTestManager/this.nextTest@dom/media/test/manifest.js:2167:12
INFO - MediaTestManager/this.runTests/<@dom/media/test/manifest.js:2062:12
INFO - AsyncMediaTestManager/this.runTests@dom/media/test/manifest.js:2061:19
INFO - startTest/<@dom/media/test/background_video.js:15:13
INFO - Async*startTest@dom/media/test/background_video.js:14:17
INFO - @dom/media/test/test_background_video_suspend_ends.html:43:12
INFO - gizmo.mp4-0 timed out!
INFO - {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"PLAYING","channels":1,"containerType":"video/mp4","hasAudio":true,"hasVideo":true,"instance":"1e4be8c3c00","rate":48000,"reader":{"audioChannels":1,"audioDecoderName":"wmf audio decoder","audioFramesDecoded":190,"audioRate":48,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":191,"numSamplesOutput":190,"pending":0,"queueSize":1,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":0,"waitingForKey":0,"waitingPromise":false},"audioType":"audio/mp4a-latm","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"blank media data decoder","videoHardwareAccelerated":false,"videoHeight":0,"videoNumSamplesOutputTotal":72,"videoNumSamplesSkippedTotal":0,"videoRate":30.000009536743164,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":48,"numSamplesOutput":44,"pending":0,"queueSize":4,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":0,"waitingForKey":0,"waitingPromise":false},"videoType":"video/avc","videoWidth":0},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":-1953184666628070100,"loadID":-454761244,"streamLength":-1953184666628070100}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":2040000,"decodedAudioEndTime":4053333,"decodedVideoEndTime":2400000,"duration":5589333,"isPlaying":true,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":true,"isStarted":false,"lastGoodPosition":2040000,"outputRate":48000,"playbackComplete":false,"startTime":0,"written":102720},"isPlaying":true,"isStarted":true},"decodedStream":{"audioQueueFinished":false,"audioQueueSize":-454761244,"data":{"audioFramesWritten":-1953184666628070100,"haveSentFinishAudio":false,"haveSentFinishVideo":false,"instance":"","lastVideoEndTime":-1953184666628070100,"lastVideoStartTime":-1953184666628070100,"nextAudioTime":-1953184666628070100,"streamAudioWritten":-1953184666628070100,"streamVideoWritten":-1953184666628070100},"instance":"","lastAudio":-1953184666628070100,"lastOutputTime":-1953184666628070100,"playing":-454761244,"startTime":-1953184666628070100},"videoSink":{"endPromiseHolderIsEmpty":false,"finished":false,"hasVideo":true,"isPlaying":true,"isStarted":true,"size":11,"videoFrameEndTime":2066666,"videoSinkEndRequestExists":false}},"mediaTime":2040000,"playState":3,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"idle"}}}
INFO - [finished gizmo.mp4-0] remaining=
INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [finished gizmo.mp4-0 t=180.08] Length of array should match number of running tests
INFO - TEST-PASS | dom/media/test/test_background_video_suspend_ends.html | [started gizmo-noaudio.mp4-1 t=180.085] Length of array should match number of running tests

Nils the failure rate is pretty low, can you take a look if someone needs to be assigned?

Flags: needinfo?(rjesup) → needinfo?(drno)

Whiteboard: [stockwell fixed][stockwel:needsowner] → [stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Jim Mathies [:jimm]

Updated

•

3 years ago

Status: REOPENED → RESOLVED

Closed: 7 years ago → 3 years ago

Flags: needinfo?(drno)

Resolution: --- → WORKSFORME

Treeherder Bug Filer

Reporter

Updated

•

2 years ago