Open Bug 1295884 Opened 3 years ago Updated 2 days ago

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

Categories

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

x86_64
Windows 10
defect

Tracking

()

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

References

(Depends on 1 open bug)

Details

(Keywords: bulk-close-intermittents, intermittent-failure, Whiteboard: [stockwell fixed][stockwel:needsowner])

Attachments

(1 obsolete file)

Flags: needinfo?(dglastonbury)
Component: Audio/Video → Audio/Video: Playback
I hadn't seen this fail on Linux before. I'll take a lot into it.
Assignee: nobody → dglastonbury
Flags: needinfo?(dglastonbury)
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.
Attachment #8784656 - Attachment is obsolete: true
I think this might be a duplicate of bug 1297429
Depends on: 1297429
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.
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)
can't comment on that particular version.
now that bug 1319987 has landed, let see how that pans out now.
Flags: needinfo?(jyavenard)
Depends on: 1339351
this looks fixed :)
Whiteboard: [stockwell fixed]
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
(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
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)
(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)
Assignee: dglastonbury → nobody
must be an event race in there... not enough bandwidth to look into this at the moment
Flags: needinfo?(jyavenard)

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 - async
MediaTestManager/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)
Whiteboard: [stockwell fixed] → [stockwell fixed][stockwel:needsowner]

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

Flags: needinfo?(rjesup)
You need to log in before you can comment on or make changes to this bug.