Intermittent dom/media/test/test_hls_player_independency.html | Test timed out.
Categories
(GeckoView :: Media, defect, P5)
Tracking
(firefox79 fixed, firefox80 fixed, firefox81 fixed)
People
(Reporter: intermittent-bug-filer, Assigned: jhlin)
References
(Regression)
Details
(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])
Attachments
(1 file)
47 bytes,
text/x-phabricator-request
|
jcristau
:
approval-mozilla-beta+
RyanVM
:
approval-mozilla-release+
|
Details | Review |
Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=302498542&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QR6NuZLZTvShqGoaAH47Mg/runs/0/artifacts/public/logs/live_backing.log
[task 2020-05-15T20:06:41.308Z] 20:00:58 INFO - 230 INFO TEST-START | dom/media/test/test_hls_player_independency.html
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - Buffered messages logged at 20:00:52
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 231 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | A valid string reason is expected
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 232 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | Reason cannot be empty
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - Buffered messages logged at 20:00:58
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 233 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | 4x3 content, the width should be 400.
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 234 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | 4x3 content, the height should be 300.
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - Buffered messages finished
[task 2020-05-15T20:06:41.308Z] 20:06:19 WARNING - 235 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_hls_player_independency.html | Test timed out.
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - reportError@SimpleTest/TestRunner.js:128:22
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 236 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"ENDED","channels":2,"containerType":"application/x-mpegurl","hasAudio":true,"hasVideo":true,"instance":"7996ee4c00","rate":22050,"reader":{"audioChannels":2,"audioDecoderName":"android decoder (remote)","audioFramesDecoded":108,"audioRate":22.049999237060547,"audioState":{"demuxEOS":1,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":1,"needInput":false,"numSamplesInput":108,"numSamplesOutput":108,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/mp4a-latm","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":1},"videoDecoderName":"android decoder (remote)","videoHardwareAccelerated":true,"videoHeight":300,"videoNumSamplesOutputTotal":145,"videoNumSamplesSkippedTotal":0,"videoRate":29.783342361450195,"videoState":{"demuxEOS":1,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":4,"needInput":false,"numSamplesInput":164,"numSamplesOutput":145,"pending":0,"queueSize":19,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/avc","videoWidth":400},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":true,"audioRequestStatus":"idle","clock":-1,"decodedAudioEndTime":5015501,"decodedVideoEndTime":5034111,"duration":5034111,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":true,"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":true,"finished":true,"hasVideo":true,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":5034111,"playState":4,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":true,"videoRequestStatus":"idle"}}}
[task 2020-05-15T20:06:41.308Z] 20:06:19 INFO - 237 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"d
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 3•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment hidden (Intermittent Failures Robot) |
Comment 5•5 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=309515373&repo=autoland&lineNumber=2417
Comment hidden (Intermittent Failures Robot) |
![]() |
||
Comment 7•5 years ago
|
||
[task 2020-07-12T19:27:08.313Z] 19:21:46 INFO - 228 INFO TEST-START | dom/media/test/test_hls_player_independency.html
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - Buffered messages logged at 19:21:36
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - 229 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | A valid string reason is expected
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - 230 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | Reason cannot be empty
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - Buffered messages logged at 19:21:42
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - 231 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | 4x3 content, the width should be 400.
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - 232 INFO TEST-PASS | dom/media/test/test_hls_player_independency.html | 4x3 content, the height should be 300.
[task 2020-07-12T19:27:08.313Z] 19:26:57 INFO - Buffered messages finished
[task 2020-07-12T19:27:08.314Z] 19:26:57 WARNING - 233 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_hls_player_independency.html | Test timed out.
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:409:16
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - reportError@SimpleTest/TestRunner.js:138:22
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:160:18
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - 234 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"ENDED","channels":2,"containerType":"application/x-mpegurl","hasAudio":true,"hasVideo":true,"instance":"769f22e400","rate":22050,"reader":{"audioChannels":2,"audioDecoderName":"android decoder (remote)","audioFramesDecoded":105,"audioRate":22.049999237060547,"audioState":{"demuxEOS":1,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":1,"needInput":false,"numSamplesInput":105,"numSamplesOutput":105,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/mp4a-latm","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"android decoder (remote)","videoHardwareAccelerated":true,"videoHeight":300,"videoNumSamplesOutputTotal":146,"videoNumSamplesSkippedTotal":0,"videoRate":29.766679763793945,"videoState":{"demuxEOS":1,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":3,"needInput":false,"numSamplesInput":146,"numSamplesOutput":146,"pending":0,"queueSize":0,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/avc","videoWidth":400},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":true,"audioRequestStatus":"idle","clock":-1,"decodedAudioEndTime":4919724,"decodedVideoEndTime":4938334,"duration":4938334,"isPlaying":false,"mediaSink":{"audioSinkWrapper":{"audioEnded":true,"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":true,"finished":true,"hasVideo":true,"isPlaying":false,"isStarted":false,"size":0,"videoFrameEndTime":0,"videoSinkEndRequestExists":false}},"mediaTime":4938334,"playState":4,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":true,"videoRequestStatus":"idle"}}}
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - 235 INFO {"EMEInfo":{"keySystem":"","sessionsInfo":""},"compositorDroppedFrames":0,"decoder":{"PlayState":"PLAYING","channels":2,"containerType":"application/x-mpegurl","hasAudio":true,"hasVideo":true,"instance":"769f236800","rate":22050,"reader":{"audioChannels":2,"audioDecoderName":"android decoder (remote)","audioFramesDecoded":24,"audioRate":22.049999237060547,"audioState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":false,"hasDemuxRequest":false,"hasPromise":false,"lastStreamSourceID":2,"needInput":false,"numSamplesInput":5,"numSamplesOutput":1,"pending":0,"queueSize":4,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"audioType":"audio/mp4a-latm","frameStats":{"droppedCompositorFrames":0,"droppedDecodedFrames":0,"droppedSinkFrames":0},"videoDecoderName":"android decoder (remote)","videoHardwareAccelerated":true,"videoHeight":234,"videoNumSamplesOutputTotal":35,"videoNumSamplesSkippedTotal":0,"videoRate":29.96927833557129,"videoState":{"demuxEOS":0,"demuxQueueSize":0,"drainState":0,"hasDecoder":true,"hasDemuxRequest":false,"hasPromise":true,"lastStreamSourceID":4,"needInput":false,"numSamplesInput":62,"numSamplesOutput":35,"pending":0,"queueSize":27,"timeTreshold":-1,"timeTresholdHasSeeked":false,"waitingForData":false,"waitingForKey":false,"waitingPromise":false},"videoType":"video/avc","videoWidth":416},"resource":{"cacheStream":{"cacheSuspended":false,"channelEnded":false,"channelOffset":0,"loadID":0,"streamLength":0}},"stateMachine":{"audioCompleted":false,"audioRequestStatus":"idle","clock":1113125,"decodedAudioEndTime":1114550,"decodedVideoEndTime":1201200,"duration":4040000,"isPlaying":true,"mediaSink":{"audioSinkWrapper":{"audioEnded":false,"audioSink":{"audioEnded":false,"hasErrored":false,"isPlaying":true,"isStarted":false,"lastGoodPosition":1113125,"outputRate":48000,"playbackComplete":false,"startTime":0,"written":53430},"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":3,"videoFrameEndTime":1134466,"videoSinkEndRequestExists":false}},"mediaTime":1113125,"playState":3,"sentFirstFrameLoadedEvent":true,"state":"","stateObj":{"isPrerolling":false},"videoCompleted":false,"videoRequestStatus":"pending"}}}
[task 2020-07-12T19:27:08.314Z] 19:26:57 INFO - 236 INFO TEST-OK | dom/media/test/test_hls_player_independency.html | took 312236ms
Logcat, https://firefoxci.taskcluster-artifacts.net/GIbZlA0gSl-ej905DHQFyQ/0/public/test_info/logcat-FA84C1A00167.log has lots of output for se
veral minutes, until the test times out:
07-12 19:21:39.146 6806 9764 D GeckoHlsAudioRenderer: positionUs = 1515000, mInputStreamEnded = false
07-12 19:21:39.153 6806 9769 D GeckoHlsVideoRenderer: positionUs = 2475000, mInputStreamEnded = false
07-12 19:21:39.153 6806 9769 D GeckoHlsAudioRenderer: positionUs = 2475000, mInputStreamEnded = false
07-12 19:21:39.156 6806 9764 D GeckoHlsVideoRenderer: positionUs = 1525000, mInputStreamEnded = false
07-12 19:21:39.156 6806 9764 D GeckoHlsAudioRenderer: positionUs = 1525000, mInputStreamEnded = false
...
07-12 19:26:48.661 6806 9769 D GeckoHlsAudioRenderer: positionUs = 311983000, mInputStreamEnded = false
07-12 19:26:48.671 6806 9769 D GeckoHlsVideoRenderer: positionUs = 311993000, mInputStreamEnded = false
07-12 19:26:48.672 6806 9769 D GeckoHlsAudioRenderer: positionUs = 311993000, mInputStreamEnded = false
07-12 19:26:48.682 6806 9769 D GeckoHlsVideoRenderer: positionUs = 312004000, mInputStreamEnded = false
07-12 19:26:48.682 6806 9769 D GeckoHlsAudioRenderer: positionUs = 312004000, mInputStreamEnded = false
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
![]() |
||
Comment 10•5 years ago
|
||
Bug 1651088 landed directly before the test failed for the first time. The failures are so frequent the test would get disabled for the failure rate. John, please investigate.
Updated•5 years ago
|
Comment 11•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 14•5 years ago
|
||
Updated•5 years ago
|
Assignee | ||
Comment 15•5 years ago
|
||
(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #10)
Bug 1651088 landed directly before the test failed for the first time. The failures are so frequent the test would get disabled for the failure rate. John, please investigate.
Thanks a lot for identifying the regression. It turns out the patch for bug 1651088 holds a lock while waiting for the player thread and could cause dead lock. Fix already uploaded for review.
Comment hidden (Intermittent Failures Robot) |
Comment 17•5 years ago
|
||
Comment 18•5 years ago
|
||
I did a bunch of autoland retriggers and it looks like this worked. Please proceed with approval requests when you're able.
Comment 19•5 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 21•5 years ago
|
||
Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp
Beta/Release Uplift Approval Request
- User impact if declined: Browser hangs when playing HLS video.
- Is this code covered by automated tests?: Yes
- Has the fix been verified in Nightly?: Yes
- Needs manual test from QE?: No
- If yes, steps to reproduce:
- List of other uplifts needed: Bug 1651088
- Risk to taking this patch: Low
- Why is the change risky/not risky? (and alternatives if risky): The patche reduces the span of lock.
- String changes made/needed: N/A
Assignee | ||
Comment 22•5 years ago
|
||
Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp
Beta/Release Uplift Approval Request
- User impact if declined: Browser hangs when playing HLS video.
- Is this code covered by automated tests?: Yes
- Has the fix been verified in Nightly?: Yes
- Needs manual test from QE?: No
- If yes, steps to reproduce:
- List of other uplifts needed: Bug 1651088
- Risk to taking this patch: Low
- Why is the change risky/not risky? (and alternatives if risky): The patch reduce the span of lock.
- String changes made/needed: N/A
Comment 23•5 years ago
|
||
Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp
approved for 80.0b8
Comment 24•5 years ago
|
||
bugherder uplift |
Comment 25•5 years ago
|
||
Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp
Approved for Fenix 79.0.5.
Comment 26•5 years ago
|
||
bugherder uplift |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 29•3 years ago
|
||
Moving some media bugs to the new GeckoView::Media component.
Description
•