Closed Bug 1546655 Opened 8 months ago Closed 6 months ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla69
Tracking Status
firefox-esr60 --- unaffected
firefox67 --- unaffected
firefox67.0.1 --- unaffected
firefox68 --- fixed
firefox69 --- fixed

People

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

References

Details

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

Attachments

(9 files)

47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review
47 bytes, text/x-phabricator-request
Details | Review

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.

Keywords: leave-open

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]

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/69e2758dbbad
Skip ambisonics.mp4 in test_streams_element_capture.html. r=padenot

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

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/eecfddb57e55
Fix test filtering in test_streams_element_capture.html. r=padenot

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

Flags: needinfo?(apehrson)
Whiteboard: [stockwell needswork:owner]

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.

Flags: needinfo?(apehrson) → needinfo?(alwu)

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

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!

Flags: needinfo?(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.

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.

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.

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

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

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

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.

Flags: needinfo?(apehrson)

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.

Flags: needinfo?(apehrson)

Depends on D32108

DecodedStream is already using this for mStartTime.

Depends on D32109

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

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

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

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Priority: P5 → P2
Pushed by pehrsons@gmail.com:
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
Status: ASSIGNED → RESOLVED
Closed: 6 months ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla69

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:
Attachment #9066641 - Flags: approval-mozilla-beta?
Attachment #9066638 - Flags: approval-mozilla-beta?
Attachment #9066639 - Flags: approval-mozilla-beta?
Attachment #9066640 - Flags: approval-mozilla-beta?
Attachment #9066642 - Flags: approval-mozilla-beta?
Attachment #9066643 - Flags: approval-mozilla-beta?

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

video playback fix, approved for 68.0b7

Attachment #9066638 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9066639 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9066640 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9066641 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9066642 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9066643 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
You need to log in before you can comment on or make changes to this bug.