Closed Bug 1473173 Opened Last year Closed Last year

Intermittent dom/media/test/test_bug686942.html | Test timed out!

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla63
Tracking Status
firefox63 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered][stockwell disable-recommended])

Attachments

(1 file)

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=186296796&repo=autoland

https://queue.taskcluster.net/v1/task/QaSWfEH3TrSDMlnrKONOUg/runs/0/artifacts/public/logs/live_backing.log

[task 2018-07-03T22:06:20.925Z]     INFO - TEST-START | dom/media/test/test_bug686942.html
[task 2018-07-03T22:09:21.111Z]     INFO - TEST-INFO | started process screentopng
[task 2018-07-03T22:09:21.682Z]     INFO - TEST-INFO | screentopng: exit 0
[task 2018-07-03T22:09:21.684Z]     INFO - Buffered messages logged at 22:06:21
[task 2018-07-03T22:09:21.684Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | A valid string reason is expected 
[task 2018-07-03T22:09:21.685Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Reason cannot be empty 
[task 2018-07-03T22:09:21.686Z]     INFO - Started Tue Jul 03 2018 22:06:21 GMT+0000 (UTC) (1530655581.076s)
[task 2018-07-03T22:09:21.687Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started small-shot.ogg-0 t=0.025] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.687Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started small-shot.m4a-1 t=0.028] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.687Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.687Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.688Z]     INFO - [finished small-shot.ogg-0] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.688Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished small-shot.ogg-0 t=0.618] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.688Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started small-shot.mp3-2 t=0.62] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.689Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.691Z]     INFO - Buffered messages logged at 22:06:22
[task 2018-07-03T22:09:21.693Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.695Z]     INFO - [finished small-shot.mp3-2] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.696Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished small-shot.mp3-2 t=1.175] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.697Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started small-shot-mp3.mp4-3 t=1.178] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.698Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.707Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.709Z]     INFO - [finished small-shot-mp3.mp4-3] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.712Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished small-shot-mp3.mp4-3 t=1.729] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.719Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started small-shot.flac-4 t=1.731] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.721Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.721Z]     INFO - Buffered messages logged at 22:06:23
[task 2018-07-03T22:09:21.724Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.725Z]     INFO - [finished small-shot.flac-4] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.726Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished small-shot.flac-4 t=2.258] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.727Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started r11025_s16_c1-short.wav-5 t=2.259] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.730Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.731Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.734Z]     INFO - [finished r11025_s16_c1-short.wav-5] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.735Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished r11025_s16_c1-short.wav-5 t=2.817] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.736Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started 320x240.ogv-6 t=2.818] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.737Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.738Z]     INFO - Buffered messages logged at 22:06:24
[task 2018-07-03T22:09:21.742Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.742Z]     INFO - [finished 320x240.ogv-6] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.744Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished 320x240.ogv-6 t=3.414] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.747Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started seek-short.webm-7 t=3.415] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.748Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.749Z]     INFO - Buffered messages logged at 22:06:25
[task 2018-07-03T22:09:21.762Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.765Z]     INFO - [finished seek-short.webm-7] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.769Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished seek-short.webm-7 t=4.006] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.771Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started vp9-short.webm-8 t=4.007] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.772Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.775Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.781Z]     INFO - [finished vp9-short.webm-8] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.786Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished vp9-short.webm-8 t=4.574] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.787Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started detodos-short.opus-9 t=4.575] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.789Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.791Z]     INFO - Buffered messages logged at 22:06:26
[task 2018-07-03T22:09:21.793Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.796Z]     INFO - [finished detodos-short.opus-9] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.797Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished detodos-short.opus-9 t=5.124] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.799Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started gizmo-short.mp4-10 t=5.125] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.800Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.802Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.805Z]     INFO - [finished gizmo-short.mp4-10] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.810Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished gizmo-short.mp4-10 t=5.755] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.810Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [started flac-s24.flac-11 t=5.757] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.811Z]     INFO - Buffered messages logged at 22:06:28
[task 2018-07-03T22:09:21.812Z]     INFO - TEST-FAIL | dom/media/test/test_bug686942.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2018-07-03T22:09:21.813Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | Should not be playing after seek to end and back to beginning 
[task 2018-07-03T22:09:21.813Z]     INFO - [finished flac-s24.flac-11] remaining= small-shot.m4a-1
[task 2018-07-03T22:09:21.816Z]     INFO - TEST-PASS | dom/media/test/test_bug686942.html | [finished flac-s24.flac-11 t=7.577] Length of array should match number of running tests 
[task 2018-07-03T22:09:21.816Z]     INFO - Buffered messages finished
[task 2018-07-03T22:09:21.818Z]     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_bug686942.html | Test timed out!
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Looks like fallout from bug 1479027.
Flags: needinfo?(apehrson)
Well, there was no underlying issue fixed here before and bug686942.html doesn't exercise any code that was touched in bug 1479027. Seems like a timing change has triggered a latent issue to me.

(In reply to Eliza Balazs [:ebalazs_] from comment #2)
> This was fixed by backing out bug
> https://bugzilla.mozilla.org/show_bug.cgi?id=733530 :
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-
> central&revision=a9dc5dc8e2b8513686ad1b1f28c9e4da6de62226&filter-
> resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&filter-resultStatus=retry&filter-
> resultStatus=usercancel&filter-resultStatus=running&filter-
> resultStatus=pending&filter-resultStatus=runnable
> 
> and then merged around:
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=3a55ffabd7478cdceb632213a4aef2c4bab58c75&filter-
> resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&filter-resultStatus=usercancel&filter-
> resultStatus=runnable&filter-resultStatus=pending&filter-
> resultStatus=running&filter-resultStatus=success&filter-
> searchStr=Linux%20mda1

That doesn't make _any_ sense. That speaks even more in favor of a latent timing-related issue.
Flags: needinfo?(apehrson)
Braindump of looking at one of the failure logs[0] in the above push.
- Looks like our failures are always small-shot.flac or small-shot.m4a. In this case the m4a fails.
- Looks like we have a MediaDecoder at 0xf71ae970 and an associated MediaDecoderStateMachine at 0xe4c40800 for the m4a.
- We can compare this to a run where the m4a works in the same test[1]. There we have a MediaDecoder at 0xf70ae970 and MediaDecoderStateMachine at 0xde39e000.
- In our failing case the MDSM goes dormant and appears to stall:
>>task 2018-08-06T14:37:18.755Z] 14:37:18     INFO - GECKO(1727) | [Child 1785: MediaPlayback #1]: D/MediaDecoder >>MediaDecoderStateMachine[0xe4c40800] state=DECODING change state to: DORMANT
[task 2018-08-06T14:37:18.758Z] 14:37:18     INFO - GECKO(1727) | [Child 1785: MediaPlayback #1]: D/MediaDecoder MediaDecoderStateMachine[0xe4c40800] state=DECODING Exiting DECODING, decoded for 0.002s

Not sure what this is pointing to, will keep looking. Figured this might be some help to others while I dig.

[0]: https://treeherder.mozilla.org/logviewer.html#?job_id=192262769&repo=try&lineNumber=46874
[1]: https://treeherder.mozilla.org/logviewer.html#?job_id=192262768&repo=try&lineNumber=45234
Could it be related to other dormant-related bugs (see the ones disabling dormant at [1]), like bug 1319292?


[1] https://searchfox.org/mozilla-central/search?q=media.dormant-on-pause-timeout-ms
Could be. In that bug it sounds like us going dormant then moving through other states is causing issue. Here we don't ever seem to move out of dormant until we time out. But dormant state could still be clobbering us somehow. I wonder what changed to cause this for the m4a and flac case. Perhaps we've always been at risk but something elsewhere changed timing.

In other try runs with logging at the test level it looks like we hit the loaded handler[0]. Assuming these failures are the same as the dormant ones I mentioned above, it seems like we're hitting the loaded handler, but the change in duration is not resulting in the seek and we just sit at dormant.

Will push to try with that dormant pref set and see what happens.

[0]: https://treeherder.mozilla.org/logviewer.html#?job_id=192236867&repo=try&lineNumber=3793
Have a failure log with all the above logging turned on, as well as the dormant pref set to prevent going dormant. The high level JS logs show some unexpected behaviour with setting the currentTime[0]. Those lines show the value of v.currentTime at the start of onloaded and at the end after it has been set to v.duration. However, for our failing case we can see that v.currentTime remains at 0.

I wonder if our seek is being eaten by something higher level before it hits the MediaDecoderStateMachine.

[0]: https://treeherder.mozilla.org/logviewer.html#?job_id=192454291&repo=try&lineNumber=51842
That's interesting! Could it be the side effect of the fact that Demux is failing? I see here the failing logs too:

[task 2018-08-07T07:05:32.670Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Reset: Reset(Audio) BEGIN
[task 2018-08-07T07:05:32.672Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Reset: Reset(Audio) END
[task 2018-08-07T07:05:32.672Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Seek: aTarget=(3369738)

[task 2018-08-07T07:05:32.830Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::OnDemuxFailed: Failed to demux audio, failure:NS_ERROR_DOM_MEDIA_END_OF_STREAM
[task 2018-08-07T07:05:32.832Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Update: Rejecting Audio promise: EOS

[task 2018-08-07T07:05:32.877Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Reset: Reset(Audio) BEGIN

[task 2018-08-07T07:05:32.883Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Reset: Reset(Audio) END
[task 2018-08-07T07:05:32.884Z] 07:05:32     INFO - GECKO(1693) | [Child 1747: MediaPlayback #1]: D/MediaFormatReader MediaFormatReader[0xe2bd4800] ::Shutdown:
jya will continue this.
Assignee: nobody → jyavenard
Rank: 15
Flags: needinfo?(drno)
Priority: P5 → P2
(In reply to Bryce Seager van Dyk (:bryce) from comment #17)
> Have a failure log with all the above logging turned on, as well as the
> dormant pref set to prevent going dormant. The high level JS logs show some
> unexpected behaviour with setting the currentTime[0]. Those lines show the
> value of v.currentTime at the start of onloaded and at the end after it has
> been set to v.duration. However, for our failing case we can see that
> v.currentTime remains at 0.
> 
> I wonder if our seek is being eaten by something higher level before it hits
> the MediaDecoderStateMachine.
> 
> [0]:
> https://treeherder.mozilla.org/logviewer.html#?job_id=192454291&repo=try&lineNumber=51842

Here's a push with explicit logging of Seek(). Should show "early exit" in the log if the call gets eaten.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=38388567267fd0302e6a562441a5add8df6017dd
(In reply to Andreas Pehrson [:pehrsons] from comment #20)
> Here's a push with explicit logging of Seek(). Should show "early exit" in
> the log if the call gets eaten.
> 
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=38388567267fd0302e6a562441a5add8df6017dd

This might be more successful.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=43130a1c3f91056f5ebecd6b6065bc161f6ff34b
Andreas' try runs should shed more light, but it does look like our seek is getting eaten around the media element[0]. In the failure case we don't get the "starting seek" line, while in the happy path we do[1].

[0]: https://treeherder.mozilla.org/logviewer.html#?job_id=192587314&repo=try&lineNumber=28976
[1]: https://treeherder.mozilla.org/logviewer.html#?job_id=192586491&repo=try&lineNumber=25719
The MediaCache reads content by block of BLOCK_SIZE bytes (currently 32kB). As such, if a content being fetched is less than BLOCK_SIZE, it will always be fully read from offset = 0. We can then seek within this buffered content regardless of the underlying HTTP connection supporting request-range or not.

test_bug686942.html is ultimately testing a racy behaviour: it attempts to seek into a resource that isn't always seekable (http.js doesn't report Range -Request support for small files). The seekable range becomes then the buffered range which at the time of loadedmetadata may not be set yet.
Comment on attachment 8998903 [details]
Bug 1473173 - Report MediaResource as seekable if we know we will never seek into underlying transport. r=bryce

Bryce Seager van Dyk (:bryce) has approved the revision.
Attachment #8998903 - Flags: review+
Pushed by jyavenard@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/13e8f0348382
Report MediaResource as seekable if we know we will never seek into underlying transport. r=bryce
https://hg.mozilla.org/mozilla-central/rev/13e8f0348382
Status: REOPENED → RESOLVED
Closed: Last yearLast year
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
You need to log in before you can comment on or make changes to this bug.