1546655 - Intermittent dom/media/test/test_streams_element_capture.html | Test timed out!

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: pehrsons [at] gmail.com

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

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

Comment 1

[Andreas Pehrson [:pehrsons]]

We seem to be hanging on ambisonics.mp4. There are existing occurrences of this file leading to an error event on both mac and linux (bug 1483259). My best guess is that this is related. For now I will skip this file in test_streams_element_capture.html as the rate is surprisingly high.

Comment 2

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Skip ambisonics.mp4 in test_streams_element_capture.html. r?padenot

Comment 3

[Andreas Pehrson [:pehrsons]]

For all the cases I've looked at of this bug, while fetching ambisonics.mp4 the log shows this:

JavaScript error: /builds/worker/workspace/build/tests/bin/components/httpd.js, line 2608: NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray]

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/69e2758dbbad
Skip ambisonics.mp4 in test_streams_element_capture.html. r=padenot

Comment 5

[Andreas Pehrson [:pehrsons]]

Bah, there's a bug in the first patch, so now linux is permafailing. Somehow it worked fine locally (also linux).

Comment 6

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Fix test filtering in test_streams_element_capture.html. r?padenot

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/eecfddb57e55
Fix test filtering in test_streams_element_capture.html. r=padenot

Comment 8

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/69e2758dbbad
https://hg.mozilla.org/mozilla-central/rev/eecfddb57e55

Comment 9

[Andreea Pavel [:apavel]]

Failure rate seems to have increase with the landing of bug 1536766, Andreas can you take a look?

Comment 10

[Andreas Pehrson [:pehrsons]]

The current failures seem to be from opus-mapping2.webm. It makes me wonder a bit if it's a separate failure or we're just pushing the failures around as we disable files.

Since I will be away the next few weeks I'll defer fixing this for now. Alastor, could you make the test skip opus-mapping2.webm for now, and follow up to see if the failures hops over to another test file? If they do we have something we need to investigate.

Comment 11

[Alastor Wu [:alwu]]

Sure, I will file a bug to skip that file and monitor this failure. Keep NI.

Comment 12

[Intermittent Failures Robot]

46 failures in 3031 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 20
• mozilla-inbound: 4
• mozilla-central: 22

Platform breakdown:

• linux64: 2
• linux64-qr: 22
• linux32: 2
• windows10-64-ccov: 15
• linux64-ccov: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1546655&startday=2019-04-22&endday=2019-04-28&tree=all

Comment 13

[Alastor Wu [:alwu]]

I checked the newest 10 faliures in reports, there are 6 timeout due to flac-s24.flac and 4 timeout due to opus-mapping2.webm.

From the log below, it seems to me that the playback might not start playing because we didn't get playing after getting canplaythrough, so that we can't get ended event and it causes timeout.

00:47:00 INFO - TEST-PASS | dom/media/test/test_streams_element_capture.html | flac-s24.flac-68 set output element .srcObject correctly
00:47:00 INFO - [00:47:00.987] flac-s24.flac-68 MediaDecoder got loadedmetadata
00:47:00 INFO - [00:47:00.989] flac-s24.flac-68 MediaStream got loadstart
00:47:01 INFO - [00:47:01.5] flac-s24.flac-68 MediaStream got suspend
00:47:01 INFO - [00:47:01.6] flac-s24.flac-68 MediaDecoder got loadeddata
00:47:01 INFO - [00:47:01.7] flac-s24.flac-68 MediaDecoder got canplay
00:47:01 INFO - [00:47:01.7] flac-s24.flac-68 MediaDecoder got canplaythrough
00:47:01 INFO - [00:47:01.7] flac-s24.flac-68 MediaDecoder got suspend
00:47:01 INFO - [00:47:01.10] flac-s24.flac-68 MediaDecoder got play
00:47:01 INFO - [00:47:01.11] flac-s24.flac-68 MediaDecoder got playing
00:47:01 INFO - [00:47:01.11] flac-s24.flac-68 MediaStream got play
00:47:01 INFO - [00:47:01.12] flac-s24.flac-68 MediaStream got waiting
00:47:01 INFO - [00:47:01.15] flac-s24.flac-68 MediaStream got loadedmetadata
00:47:01 INFO - [00:47:01.15] flac-s24.flac-68 MediaStream got loadeddata
00:47:01 INFO - [00:47:01.16] flac-s24.flac-68 MediaStream got canplay
00:47:01 INFO - [00:47:01.17] flac-s24.flac-68 MediaStream got playing
00:47:01 INFO - [00:47:01.18] flac-s24.flac-68 MediaStream got canplaythrough
00:47:04 INFO - [00:47:04.586] flac-s24.flac-68 MediaDecoder got waiting
00:47:06 INFO - [00:47:06.454] flac-s24.flac-68 MediaDecoder got canplay
00:47:06 INFO - [00:47:06.455] flac-s24.flac-68 MediaDecoder got playing
00:47:06 INFO - [00:47:06.455] flac-s24.flac-68 MediaDecoder got canplaythrough
00:47:06 INFO - [00:47:06.528] flac-s24.flac-68 MediaDecoder got suspend
00:47:08 INFO - [00:47:08.413] flac-s24.flac-68 MediaDecoder got suspend
00:47:08 INFO - [00:47:08.413] flac-s24.flac-68 MediaDecoder got canplaythrough
00:49:59 INFO - flac-s24.flac-68 timed out!

Comment 14

[Alastor Wu [:alwu]]

No, actually we won't expect that the playing event should be dispatched after canplaythrough, so it feels more like that we started playback but didn't fire ended event.

Comment 15

[Alastor Wu [:alwu]]

Most of failures happened when MediaDecoder got waiting event after the first time it got playing, so I'm wondering whether there is a bug that decoder couldn't start decoding correctly when the ready state changes.

Comment 16

[Alastor Wu [:alwu]]

From the log, it didn't contain many useful information, I couldn't have a good explaination for this intermittent faliure, and I don't want to disable another test file to rounding this error off (That is the last option).

As the error rate is reducing, I think we can wait several days to see whether we really need to disable those files.

Comment 17

[Andreea Pavel [:apavel]]

Alastor, the failure rate might have been reduced due to being weekend and there were not that many pushes.

From OF I see that the failure rate is increasing again: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-24&endday=2019-05-01&tree=trunk&bug=1546655

Comment 18

[Alastor Wu [:alwu]]

OK, I can disable those tests first and see whether we would still hit this failure.

Comment 19

[Alastor Wu [:alwu]]

Attachment: Bug 1546655 - Skip 'flac-s24.flac' and 'opus-mapping2.webm' in test_streams_element_capture.html

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6b2c2ad50bd0
Skip 'flac-s24.flac' and 'opus-mapping2.webm' in test_streams_element_capture.html r=padenot

Comment 21

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/6b2c2ad50bd0

Comment 22

[Intermittent Failures Robot]

27 failures in 4131 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• try: 1
• mozilla-central: 14
• mozilla-inbound: 3

Platform breakdown:

• linux64-qr: 13
• windows10-64-ccov: 11
• linux64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1546655&startday=2019-04-29&endday=2019-05-05&tree=all

Comment 23

[Alastor Wu [:alwu]]

There are still some intermittent failures, but the fail rate is low. I guess there is still a problem in capturing stream which results in not to dispatch ended event. Ni Andreas for further invetigation.

Comment 24

[Intermittent Failures Robot]

2 failures in 4705 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• windows10-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1546655&startday=2019-05-06&endday=2019-05-12&tree=all

Comment 25

[Intermittent Failures Robot]

1 failures in 4658 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1546655&startday=2019-05-13&endday=2019-05-19&tree=all

Comment 26

[Andreas Pehrson [:pehrsons]]

I've been debugging on try for a few days. It seems that the reason some files are stalling is the DecodedStream-equivalent to https://searchfox.org/mozilla-central/rev/f4c39907e0b527dc4b9356a1eeb8c6e6c62d383a/dom/media/mediasink/VideoSink.cpp#236-241

The fix should be easy.

Comment 27

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Re-enable tests. r?jya

Depends on D32108

Comment 28

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Switch to NullableTimeUnit where applicable in DecodedStream. r?jya

DecodedStream is already using this for mStartTime.

Depends on D32109

Comment 29

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Add AudioQueue info to DecodedStream's debug info. r?jya

Depends on D32110

Comment 30

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Call SendData() on SetPlaying(true). r?jya

The following sequence in DecodedStream could lead to a stall for a captured
media element:

• MediaDecoder decodes some data, DecodedStream sends it out
• MediaDecoder pauses for buffering, DecodedStream sees SetPlaying(false)
• MediaDecoder decodes until the end, DecodedStream doesn't send since it's
  not playing
• MediaDecoder starts playing again, DecodedStream sees SetPlaying(true)

At the last step above, SetPlaying(true) doesn't trigger SendData() so no data
is sent out. Since all data has already been decoded, nothing can trigger
SendData() anymore. This patch fixes this by calling SendData() on SetPlaying().

Depends on D32111

Comment 31

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Remove racy assert. r?jya

This assert can be racy if the following sequence happens:
SetPlaying() -- watch manager schedules SendData()
Stop() -- unwatches mPlaying, resets mStartTime
SendData() -- fails the assert

SendData handles the case where mStartTime is unset at runtime already through
the mData check, further making this assert unnecessary.

Depends on D32112

Comment 32

[Andreas Pehrson [:pehrsons]]

Attachment: Bug 1546655 - Modernize test_streams_element_capture.html. r?jib

This async/await-ifies the test to put checks in logical order.
It also, as a drive-by, adds v.token = token since this is a cue to the test
framework in manifest.js to mozDumpDebugInfo() on the right element after
timeout of a token.

Depends on D32113

Comment 33

[Intermittent Failures Robot]

3 failures in 4730 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows10-64-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1546655&startday=2019-05-20&endday=2019-05-26&tree=all

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/04eea44d8817
Re-enable tests. r=jya
https://hg.mozilla.org/integration/autoland/rev/c8e99fe9fdcc
Switch to NullableTimeUnit where applicable in DecodedStream. r=jya
https://hg.mozilla.org/integration/autoland/rev/4b232f6bc673
Add AudioQueue info to DecodedStream's debug info. r=jya
https://hg.mozilla.org/integration/autoland/rev/181b12bf15f2
Call SendData() on SetPlaying(true). r=jya
https://hg.mozilla.org/integration/autoland/rev/317b31b87aee
Remove racy assert. r=jya
https://hg.mozilla.org/integration/autoland/rev/0b8c2f457b6e
Modernize test_streams_element_capture.html. r=jib

Comment 35

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/04eea44d8817
https://hg.mozilla.org/mozilla-central/rev/c8e99fe9fdcc
https://hg.mozilla.org/mozilla-central/rev/4b232f6bc673
https://hg.mozilla.org/mozilla-central/rev/181b12bf15f2
https://hg.mozilla.org/mozilla-central/rev/317b31b87aee
https://hg.mozilla.org/mozilla-central/rev/0b8c2f457b6e

Comment 36

[Andreas Pehrson [:pehrsons]]

Comment on attachment 9066641 [details]
Bug 1546655 - Call SendData() on SetPlaying(true). r?jya

Beta/Release Uplift Approval Request

• User impact if declined: Playback of some videos may stall when captured to a MediaStream
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: No
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): The non-test-only bits of these patches are rather trivial.
• String changes made/needed:

Comment 37

[Julien Cristau [:jcristau]]

Comment on attachment 9066638 [details]
Bug 1546655 - Re-enable tests. r?jya

video playback fix, approved for 68.0b7

Comment 38

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/releases/mozilla-beta/rev/083d8b196e64
https://hg.mozilla.org/releases/mozilla-beta/rev/2a54b1e72bae
https://hg.mozilla.org/releases/mozilla-beta/rev/facb1c6c89a5
https://hg.mozilla.org/releases/mozilla-beta/rev/b53f13005bd3
https://hg.mozilla.org/releases/mozilla-beta/rev/3c9393f08fc6
https://hg.mozilla.org/releases/mozilla-beta/rev/18e5f48ade65