Closed Bug 1598087 Opened 5 years ago Closed 4 years ago

Intermittent dom/media/test/test_streams_element_capture_reset.html | removetrack event received on {2c371e2f-0ccf-4e82-8e89-957115abc648} unexpectedly

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla73
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox71 --- unaffected
firefox72 --- fixed
firefox73 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Attachments

(1 file)

Bug 1598087 - Don't wait for currentTime to progress so playback doesn't end unexpectedly. r?jib
47 bytes, text/x-phabricator-request
Details | Review

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=277204069&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/B3GLFpWvTmWOAma_n7oJSw/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/B3GLFpWvTmWOAma_n7oJSw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 55 INFO TEST-PASS | dom/media/test/test_streams_element_capture_reset.html | Got 0.44, expected at least 0.399; checking vout.currentTime after seeking and playing through again
[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 56 INFO 320x240.ogv:v GOT EVENT timeupdate currentTime=0 paused=false ended=false readyState=0
[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 57 INFO 320x240.ogv:vout GOT EVENT playing currentTime=0.44 paused=false ended=false readyState=4
[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 58 INFO 320x240.ogv:v GOT EVENT playing currentTime=0 paused=false ended=false readyState=4
[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 59 INFO 320x240.ogv:vout GOT EVENT timeupdate currentTime=0.6933333333333334 paused=false ended=false readyState=4
[task 2019-11-20T16:21:14.859Z] 16:21:14 INFO - 60 INFO 320x240.ogv:v GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - 61 INFO 320x240.ogv:v GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - 62 INFO 320x240.ogv:v GOT EVENT timeupdate currentTime=0.266664 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - 63 INFO 320x240.ogv:v GOT EVENT pause currentTime=0.266664 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - 64 INFO 320x240.ogv:v GOT EVENT ended currentTime=0.266664 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - Buffered messages finished
[task 2019-11-20T16:21:14.860Z] 16:21:14 WARNING - 65 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_streams_element_capture_reset.html | removetrack event received on {2c371e2f-0ccf-4e82-8e89-957115abc648} unexpectedly
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - unexpected@dom/media/test/test_streams_element_capture_reset.html:29:5
[task 2019-11-20T16:21:14.860Z] 16:21:14 INFO - 66 INFO 320x240.ogv:vout GOT EVENT timeupdate currentTime=0.7226666666666667 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.861Z] 16:21:14 INFO - 67 INFO 320x240.ogv:vout GOT EVENT timeupdate currentTime=0.7226666666666667 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.861Z] 16:21:14 INFO - 68 INFO 320x240.ogv:vout GOT EVENT pause currentTime=0.7226666666666667 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.861Z] 16:21:14 INFO - 69 INFO 320x240.ogv:vout GOT EVENT ended currentTime=0.7226666666666667 paused=true ended=true readyState=2
[task 2019-11-20T16:21:14.861Z] 16:21:14 WARNING - 70 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_streams_element_capture_reset.html | ended event received on vout unexpectedly
[task 2019-11-20T16:21:14.861Z] 16:21:14 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-11-20T16:21:14.861Z] 16:21:14 INFO - unexpected@dom/media/test/test_streams_element_capture_reset.html:29:5
[task 2019-11-20T16:24:11.343Z] 16:24:11 INFO - Failed to get top activity, retrying, once...
[task 2019-11-20T16:26:07.350Z] 16:26:07 WARNING - 71 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_streams_element_capture_reset.html | Test timed out.
[task 2019-11-20T16:26:07.350Z] 16:26:07 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-11-20T16:26:07.350Z] 16:26:07 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-11-20T16:26:07.350Z] 16:26:07 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-11-20T16:26:08.370Z] 16:26:08 INFO - 72 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"ENDED","channels":0,"containerType":"application/ogg","hasAudio":false,"hasVideo":true,"instance":"7aa77d5c2000","rate":0,"reader":{"audioChannels":0,"audioDecoderName":"unavailable","audioFramesDecoded":0,"audioRate":0,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"none","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"theora video decoder","videoHardwareAccelerated":false,"videoHeight":240,"videoNumSamplesOutputTotal":8,"videoNumSamplesSkippedTotal":0,"videoRate":30.00029945373535,"videoState":{"demuxEOS":1,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":-1,"needInput":false,"numSamplesInput":8,"numSamplesOutput":8,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/theora","videoWidth":320},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":-1,"decodedAudioEndTime":0,"decodedVideoEndTime":266664,"duration":266664,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":false,"isStarted":false,"lastGoodPosition":0,"outputRate":0,"playbackComplete":false,"startTime":0,"written":0},"isPlaying":false,"isStarted":false},"decodedStream":{"audioQueueFinished":false,"audioQueueSize":0,"data":{"audioFramesWritten":0,"haveSentFinishAudio":false,"haveSentFinishVideo":false,"instance":"","lastVideoEndTime":0,"lastVideoStartTime":0,"nextAudioTime":0,"streamAudioWritten":0,"streamVideoWritten":0},"instance":"7aa77d583800","lastAudio":-1,"lastOutputTime":0,"playing":0,"startTime":-1},"videoSink":{"endPromiseHolderIsEmpty":true,"finished":true,"hasVideo":false,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":266664,"playState":4,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"idle"}}}
[task 2019-11-20T16:26:08.372Z] 16:26:08 INFO - 73 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"","channels":0,"containerType":"","hasAudio":false,"hasVideo":false,"instance":"","rate":0,"reader":{"audioChannels":0,"audioDecoderName":"","audioFramesDecoded":0,"audioRate":0,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"","videoHardwareAccelerated":false,"videoHeight":0,"videoNumSamplesOutputTotal":0,"videoNumSamplesSkippedTotal":0,"videoRate":0,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"","videoWidth":0},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"","clock":0,"decodedAudioEndTime":0,"decodedVideoEndTime":0,"duration":0,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":false,"isStarted":false,"lastGoodPosition":0,"outputRate":0,"playbackComplete":false,"startTime":0,"written":0},"isPlaying":false,"isStarted":false},"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":false,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":0,"playState":0,"sentFirstFrameLoadedEvent":false,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":""}}}
[task 2019-11-20T16:26:08.374Z] 16:26:08 INFO - 74 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":2,"decoder":{"PlayState":"","channels":0,"containerType":"","hasAudio":false,"hasVideo":false,"instance":"","rate":0,"reader":{"audioChannels":0,"audioDecoderName":"","audioFramesDecoded":0,"audioRate":0,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"","videoHardwareAccelerated":false,"videoHeight":0,"videoNumSamplesOutputTotal":0,"videoNumSamplesSkippedTotal":0,"videoRate":0,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":0,"needInput":false,"numSamplesInput":0,"numSamplesOutput":0,"pending":0,"queueSize":0,"timeTreshold":0,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"","videoWidth":0},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"","clock":0,"decodedAudioEndTime":0,"decodedVideoEndTime":0,"duration":0,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":false,"isStarted":false,"lastGoodPosition":0,"outputRate":0,"playbackComplete":false,"startTime":0,"written":0},"isPlaying":false,"isStarted":false},"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":false,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":0,"playState":0,"sentFirstFrameLoadedEvent":false,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":""}}}
[task 2019-11-20T16:26:08.374Z] 16:26:08 INFO - 75 INFO TEST-OK | dom/media/test/test_streams_element_capture_reset.html | took 301017ms
[task 2019-11-20T16:26:08.374Z] 16:26:08 INFO - 76 INFO TEST-START | Shutdown
[task 2019-11-20T16:26:08.374Z] 16:26:08 INFO - 77 INFO Passed: 26
[task 2019-11-20T16:26:08.374Z] 16:26:08 WARNING - 78 INFO Failed: 3
[task 2019-11-20T16:26:08.374Z] 16:26:08 WARNING - One or more unittests failed.
[task 2019-11-20T16:26:08.374Z] 16:26:08 INFO - 79 INFO Todo: 0
[task 2019-11-20T16:26:08.375Z] 16:26:08 INFO - 80 INFO Mode: e10s
[task 2019-11-20T16:26:08.375Z] 16:26:08 INFO - 81 INFO Slowest: 301018ms - /tests/dom/media/test/test_streams_element_capture_reset.html
[task 2019-11-20T16:26:08.375Z] 16:26:08 INFO - 82 INFO TEST-INFO | Ran 2 Loops
[task 2019-11-20T16:26:08.375Z] 16:26:08 INFO - 83 INFO SimpleTest FINISHED
[task 2019-11-20T16:26:10.503Z] 16:26:10 INFO - wait for org.mozilla.geckoview.test complete; top activity=com.android.launcher3
[task 2019-11-20T16:26:10.606Z] 16:26:10 INFO - remoteautomation.py | Application ran for: 0:05:08.729793

Keywords: regression
Whiteboard: [retriggered]

I have this in pernosco, taking a look.
https://pernos.co/debug/4WrfOhQxe0vnTcSG04o0ng/index.html

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Flags: needinfo?(apehrson)

This looks like a test issue, where the media element ends while we're waiting for a "timeupdate" that doesn't come until playback has already ended. It's not entirely surprising given how short this video is.

While waiting for "timeupdate" for a currentTime >0 playback could end before
we're done waiting. This causes both unexpected test failures and a timeout.

The simplest way out of this seems to be to first wait for the play promise to
resolve so we know the output tracks are available; second to set currentTime to
0 even if it already is 0. By spec this still seeks, so it is fine.

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/5789d8f7d7bf
Don't wait for currentTime to progress so playback doesn't end unexpectedly. r=jib

https://hg.mozilla.org/mozilla-central/rev/5789d8f7d7bf

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox73: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla73

Please uplift this test-only patch to beta 72.

status-firefox71: --- → unaffected
status-firefox72: --- → affected
status-firefox-esr68: --- → unaffected
Whiteboard: [retriggered] → [retriggered][checkin-needed-beta]

https://hg.mozilla.org/releases/mozilla-beta/rev/d744c5ad0fd0

status-firefox72: affected → fixed
Whiteboard: [retriggered][checkin-needed-beta] → [retriggered]
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: