Closed Bug 1638452 Opened 5 years ago Closed 5 years ago

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

Categories

(GeckoView :: Media, defect, P5)

defect

Tracking

(firefox79 fixed, firefox80 fixed, firefox81 fixed)

RESOLVED FIXED
81 Branch
Tracking Status
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)

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

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
[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
Component: Testing → General
Product: Firefox for Android → GeckoView

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.

Flags: needinfo?(jolin)
Regressed by: 1651088
Has Regression Range: --- → yes
Keywords: regression
Assignee: nobody → jolin

(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.

Flags: needinfo?(jolin)
Pushed by rvandermeulen@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/06456f429c22 don't hold lock while waiting player thread. r=snorp,geckoview-reviewers

I did a bunch of autoland retriggers and it looks like this worked. Please proceed with approval requests when you're able.

Flags: needinfo?(jolin)
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → 81 Branch

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
Flags: needinfo?(jolin)
Attachment #9169336 - Flags: approval-mozilla-beta?

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
Attachment #9169336 - Flags: approval-mozilla-release?

Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp

approved for 80.0b8

Attachment #9169336 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Comment on attachment 9169336 [details]
Bug 1638452 - don't hold lock while waiting player thread. r?snorp

Approved for Fenix 79.0.5.

Attachment #9169336 - Flags: approval-mozilla-release? → approval-mozilla-release+

Moving some media bugs to the new GeckoView::Media component.

Component: General → Media
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: