Assertion failure: outputTrack->GetEnd() == GraphTimeToStreamTime(interval.mStart) (Samples missing), at dom/media/TrackUnionStream.cpp:279

RESOLVED FIXED in Firefox 35, Firefox OS v2.1

Status

()

Core
WebRTC: Audio/Video
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: pehrsons, Assigned: pehrsons)

Tracking

Trunk
mozilla37
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox34 wontfix, firefox35 fixed, firefox36 fixed, firefox37 fixed, b2g-v1.4 wontfix, b2g-v2.0 wontfix, b2g-v2.0M wontfix, b2g-v2.1 fixed, b2g-v2.2 fixed)

Details

Attachments

(2 attachments, 2 obsolete attachments)

(Assignee)

Description

3 years ago
A patch on bug 1073406 makes us hit this assertion a lot. Will have to be resolved before bug 1073406 can land.

Some cases to show frequency, platforms, etc:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=e1e1feb3f9d0
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=90ae4824baa8
(Assignee)

Updated

3 years ago
Blocks: 1073406
(Assignee)

Updated

3 years ago
Assignee: nobody → pehrsons
Status: NEW → ASSIGNED
(Assignee)

Comment 1

3 years ago
Looking at the logs from when this fails, I always see "WARNING: Slice out of range: 'aStart >= 0 && aEnd <= aSource.mDuration', file /builds/slave/try-lx-d-000000000000000000000/build/src/media/webrtc/signaling/../../../dom/media/MediaSegment.h, line 317"

Bug 991273 turned an assert into this warning. We might be looking at the same issue for this bug, as was the origin of that bug.


See for instance this try run, with some extra logs: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=3ba38bca2e90
Log file: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/pehrsons@gmail.com-3ba38bca2e90/try-linux-debug/try_ubuntu32_vm-debug_test-mochitest-3-bm01-tests1-linux32-build1613.txt.gz
Depends on: 991273
(Assignee)

Comment 2

3 years ago
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #1)
> See for instance this try run, with some extra logs:
> https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=3ba38bca2e90
> Log file:
> http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/pehrsons@gmail.com-
> 3ba38bca2e90/try-linux-debug/try_ubuntu32_vm-debug_test-mochitest-3-bm01-
> tests1-linux32-build1613.txt.gz

And here's the relevant snippet:

05:06:39     INFO -  ##### 0xaa37f100 outputTrack->GetEnd()=675328, interval.mStart=675328
05:06:39     INFO -  ##### 0x83449d00 outputTrack->GetEnd()=682227, interval.mStart=682227
05:06:39     INFO -  [1814] WARNING: Slice out of range: 'aStart >= 0 && aEnd <= aSource.mDuration', file /builds/slave/try-lx-d-000000000000000000000/build/src/media/webrtc/signaling/../../../dom/media/MediaSegment.h, line 317
05:06:39     INFO -  ##### 0x83449d00 outputTrack->GetEnd()=683566, interval.mStart=682995
05:06:39     INFO -  Assertion failure: outputTrack->GetEnd() == GraphTimeToStreamTime(interval.mStart) (Samples missing), at /builds/slave/try-lx-d-000000000000000000000/build/src/dom/media/TrackUnionStream.cpp:283
05:07:01     INFO -  #01: mozilla::TrackUnionStream::CopyTrackData(mozilla::StreamBuffer::Track*, unsigned int, long long, long long, bool*) [dom/media/TrackUnionStream.cpp:245]
05:07:01     INFO -  #02: mozilla::TrackUnionStream::ProcessInput(long long, long long, unsigned int) [dom/media/TrackUnionStream.cpp:108]
05:07:01     INFO -  #03: mozilla::MediaStreamGraphImpl::Process(long long, long long) [dom/media/MediaStreamGraph.cpp:1328]
05:07:01     INFO -  #04: mozilla::MediaStreamGraphImpl::OneIteration(long long, long long, long long, long long) [xpcom/glue/Monitor.h:78]
05:07:01     INFO -  #05: mozilla::AudioCallbackDriver::DataCallback(float*, long) [dom/media/GraphDriver.cpp:918]
05:07:01     INFO -  #06: stream_request_callback [media/libcubeb/src/cubeb_pulse.c:199]
05:07:02     INFO -  TEST-INFO | Main app process: killed by out-of-range signal, number 117
05:07:02     INFO -  562 ERROR TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/identity/test_getIdentityAssertion.html | application terminated with exit code -11
(Assignee)

Comment 3

3 years ago
I haven't been able to figure out why it only happens on try yet.

I've ruled out cpu load by running the test a couple of iterations on my linux machine with one real-time scheduled `yes` process per core. Firefox was left with maybe 5% of one of the cores but still passed the tests successfully.
(Assignee)

Comment 4

3 years ago
I see a pattern in that one TrackUnionStream ends just before AppendSlice hits its assertion. Though it's always different from the TrackUnionStream that hits the assertion itself.

It can be seen in all logs here:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=ce9640b9f4d5

Typically like this:
22:26:52     INFO -  ##### 0x8840ee00 outputTrack->GetEnd()=663168, interval.mStart=663168 @@@ interval.mEnd=664064, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=0
22:26:52     INFO -  ##### 0xa2180c00 outputTrack->GetEnd()=666752, interval.mStart=666752 @@@ interval.mEnd=667648, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=1
22:26:52     INFO -  ##### 0x8840ee00 outputTrack->GetEnd()=664064, interval.mStart=664064 @@@ interval.mEnd=664960, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=1
22:26:52     INFO -  ##### 0xa1e5b800 outputTrack->GetEnd()=672966, interval.mStart=672966 @@@ interval.mEnd=673862, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=0
22:26:52     INFO -  Assertion failure: aStart >= 0 && aEnd <= aSource.mDuration (Slice out of range), at /builds/slave/try-lx-d-000000000000000000000/build/src/media/webrtc/signaling/../../../dom/media/MediaSegment.h:317
22:27:15     INFO -  #01: mozilla::MediaSegmentBase<mozilla::AudioSegment, mozilla::AudioChunk>::AppendSliceInternal(mozilla::MediaSegmentBase<mozilla::AudioSegment, mozilla::AudioChunk> const&, long long, long long) [dom/media/MediaSegment.h:317]
22:27:15     INFO -  #02: mozilla::TrackUnionStream::CopyTrackData(mozilla::StreamBuffer::Track*, unsigned int, long long, long long, bool*) [dom/media/TrackUnionStream.cpp:290]
22:27:15     INFO -  #03: mozilla::TrackUnionStream::ProcessInput(long long, long long, unsigned int) [dom/media/TrackUnionStream.cpp:108]
22:27:15     INFO -  #04: mozilla::MediaStreamGraphImpl::Process(long long, long long) [dom/media/MediaStreamGraph.cpp:1328]
22:27:15     INFO -  #05: mozilla::MediaStreamGraphImpl::OneIteration(long long, long long, long long, long long) [xpcom/glue/Monitor.h:78]
22:27:15     INFO -  #06: mozilla::AudioCallbackDriver::DataCallback(float*, long) [dom/media/GraphDriver.cpp:918]
22:27:15     INFO -  #07: stream_request_callback [media/libcubeb/src/cubeb_pulse.c:199]
(Assignee)

Comment 5

3 years ago
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=2636d72e33a2

We're sometimes copying too much data into outputTrack?

23:23:13 INFO - ##### 0x92a8fc00 outputTrack->GetEnd()=660148, interval.mStart=660148 @@@ interval.mEnd=660660, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=0
23:23:13 INFO - [1788] WARNING: Slice out of range: 'aStart >= 0 && aEnd <= aSource.mDuration', file /builds/slave/try-lx-d-000000000000000000000/build/src/media/webrtc/signaling/../../../dom/media/MediaSegment.h, line 317
23:23:13 INFO - ##### 0x92a8fc00 outputTrack->GetEnd()=663214, interval.mStart=660660 @@@ interval.mEnd=661172, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=0
23:23:13 INFO - Assertion failure: outputTrack->GetEnd() == GraphTimeToStreamTime(interval.mStart) (Samples missing), at /builds/slave/try-lx-d-000000000000000000000/build/src/dom/media/TrackUnionStream.cpp:286
(Assignee)

Comment 6

3 years ago
So now I have something interesting.

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=c93d4e141b40

From the log:
00:45:52     INFO -  ##### 0xa2218b00 outputTrack->GetEnd()=194481, interval.mStart=194481 @@@ interval.mEnd=194993, aInputTrack->GetType()=Audio, aInputTrack->IsEnded()=0, aInputTrack->GetSegment()->GetDuration()=194481
00:45:52     INFO -  Assertion failure: aStart >= 0 && aEnd <= aSource.mDuration (Slice out of range), at /builds/slave/try-lx-d-000000000000000000000/build/src/media/webrtc/signaling/../../../dom/media/MediaSegment.h:317

The interval which we want to append to the track is (194481, 194993). But the segment we want to copy from ends at 194481. I have another try run underways that takes the segment's duration/end point into account. Let's see what that gives, here: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=3ee290e0d924
(Assignee)

Comment 7

3 years ago
That didn't do it. My bad, too naive - probably fails when the input track is blocked.
(Assignee)

Comment 8

3 years ago
Sneaky sneaky, but I finally managed to reproduce this issue on linux. You need to use the real test media devices on the system, instead of having fake media streams in gecko.

Set it up by checking the code for using them here: http://dxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#996

Then to run with them do `./mach mochitest <test> --use-test-media-devices`.
All mochitests are run on Try server with this option on?
(Assignee)

Comment 10

3 years ago
(In reply to JW Wang [:jwwang] from comment #9)
> All mochitests are run on Try server with this option on?

Yep, see this log from try on linux: http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/pehrsons@gmail.com-94c07a8ee18d/try-linux-debug/try_ubuntu32_vm-debug_test-mochitest-3-bm06-tests1-linux32-build2623.txt.gz

Search for "TEST DEVICES" and you'll find:
> 21:06:11     INFO -  TEST DEVICES: Using media devices:
> 21:06:11     INFO -  audio: Sine source at 440 Hz
> 21:06:11     INFO -  video: Dummy video device

Search dxr for "Sine source at 440Hz" and you can see it only comes from that option being on:
http://dxr.mozilla.org/mozilla-central/search?q=%22Sine+source+at+440+Hz%22&case=true&redirect=true
Since this option is default off when we run mochitests locally, it makes the test environment different between our local computer and the Try server and make some problems harder to reproduce locally...
(Assignee)

Comment 12

3 years ago
Created attachment 8534912 [details] [diff] [review]
Fix MediaEngineWebRTCAudioSource shutdown with multiple source streams

Found it. Works on my linux vm.

We're calling Shutdown() which calls Stop() (which my patch edits) for two different sources. The first one is removed from mSources but it's track aID is not ended. The second one is removed and ended properly.

The patch fixes this to always end the track if the source stream was successfully removed from the audio source.

try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=a3b5f148d92a
This assert is showing up in bug 1104086 as well.
(Assignee)

Comment 14

3 years ago
The try still shows some oranges, but they're for the same issue on video sources - so an easy fix. Seems like this fixed the issue with mismatching stream final times as well, sweet!
Component: Video/Audio → WebRTC: Audio/Video
(Assignee)

Comment 15

3 years ago
Created attachment 8535436 [details] [diff] [review]
Fix shutdown of MediaEngineWebRTC sources with multiple attached streams

Now fixed for both MediaEngineWebRTCAudio and -Video.

Bug 1073406 before patch:https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=e1e1feb3f9d0
Bug 1073406 after patch: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=4117ba3f1936
On m-c: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=7648dad43281
Attachment #8534912 - Attachment is obsolete: true
Attachment #8535436 - Flags: review?(rjesup)
(Assignee)

Comment 16

3 years ago
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #13)
> This assert is showing up in bug 1104086 as well.

The tests failing on bug 1104086 seem to all be involving getUserMedia so we're most likely looking at the same cause.
Blocks: 1104086
(Assignee)

Comment 17

3 years ago
I also take it as likely that this was causing the failures on bug 991273. We could try to revert it.
Blocks: 991273
No longer depends on: 991273
(Assignee)

Comment 18

3 years ago
Created attachment 8535449 [details] [diff] [review]
Revert bug 991273

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=40f1a380ebd8
(Assignee)

Comment 19

3 years ago
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #14)
> Seems like this fixed the issue with mismatching
> stream final times as well, sweet!

Hmm, not quite. They're still there to some extent. Different issue caused by bug 1073406 though.
(Assignee)

Comment 20

3 years ago
Comment on attachment 8535449 [details] [diff] [review]
Revert bug 991273

Looks good so far.

Paul, you think we should restore the assert with my fix?
Attachment #8535449 - Flags: review?(padenot)
(Assignee)

Comment 21

3 years ago
Uhm, so bug 991273 showed up mostly on android and mac so we should definitely test on those as well.

Oh, doesn't seem to be debug builds for android on try?

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=d69226d7bf91
try: -b d -p android -u none -t none ?
Hrm, that's really weird.
(Assignee)

Comment 24

3 years ago
Stuff is happening in bug 1073772 apparently. Let's see what they say over there.

Updated

3 years ago
Attachment #8535436 - Flags: review?(rjesup) → review+
(Assignee)

Comment 25

3 years ago
Comment on attachment 8535449 [details] [diff] [review]
Revert bug 991273

Nope, there's still something going on.

From https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=d69226d7bf91
Attachment #8535449 - Attachment is obsolete: true
Attachment #8535449 - Flags: review?(padenot)
(Assignee)

Comment 26

3 years ago
Repasting the try since we've had quite some spam in between :)

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=7648dad43281
Keywords: checkin-needed
https://hg.mozilla.org/integration/mozilla-inbound/rev/9fa6f8d6c5f3

Does this affect any older releases? i.e. should we consider backporting?
Keywords: checkin-needed
(Assignee)

Comment 28

3 years ago
Comment on attachment 8535436 [details] [diff] [review]
Fix shutdown of MediaEngineWebRTC sources with multiple attached streams

Yeah, the bug is around in both aurora and beta. Note that in beta, the patch still applies cleanly but the file is in a different location (content/media instead of dom/media)

Approval Request Comment
[Feature/regressing bug #]:
[User impact if declined]: When playing one webrtc stream in two (or more) media elements, only one of the streams' tracks will be properly shut down. Unclear how or if this propagates to users. It's been around since Firefox 20 (bug 811757) so it's at least nothing major.
[Describe test coverage new/current, TBPL]: Tested in CI on m-c with bug 1073406 (yet to land), which exposed it.
[Risks and why]: Low risk. Simple logic fix.
[String/UUID change made/needed]: None
Attachment #8535436 - Flags: approval-mozilla-beta?
Attachment #8535436 - Flags: approval-mozilla-aurora?
https://hg.mozilla.org/mozilla-central/rev/9fa6f8d6c5f3

Do we want this on b2g34 (v2.1) as well?
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
(Assignee)

Comment 30

3 years ago
Created attachment 8536742 [details] [diff] [review]
[B2G 34] Fix shutdown of MediaEngineWebRTC sources with multiple attached streams (carries r=jesup)

B2G 34 needed a slight touch.
Attachment #8536742 - Flags: review+
status-b2g-v2.1: --- → affected
status-b2g-v2.2: --- → fixed
status-firefox34: --- → wontfix
status-firefox35: --- → affected
status-firefox36: --- → affected
status-firefox37: --- → fixed
Comment on attachment 8536742 [details] [diff] [review]
[B2G 34] Fix shutdown of MediaEngineWebRTC sources with multiple attached streams (carries r=jesup)

See comment 28.
Attachment #8536742 - Flags: approval-mozilla-b2g34?
(Assignee)

Comment 32

3 years ago
I was trying to find if we're actually hit by this in any cases except shutdown on 34 (and beyond, or on trunk for that matter..). We are. It could happen if there are two gUM streams using the same hardware and MediaStreamTrack::Stop is called for a track hooked up to that hardware. The track will not end in this case, but the MediaStreamGraph will keep copying data to it. Still unclear if this hits the user in any way though.

This applies to 30 and 32 as well (and the last patch applies cleanly there). Any reason to not request approval for those?
Flags: needinfo?(ryanvm)
30 and 32 are only accepting fixes for partner blockers or critical security issues at this point. So unless there's strong proof that this is severely affecting people, it's not likely to meet that bar for approval.
status-b2g-v1.4: --- → wontfix
status-b2g-v2.0: --- → wontfix
status-b2g-v2.0M: --- → wontfix
Flags: needinfo?(ryanvm)
Attachment #8535436 - Flags: approval-mozilla-beta?
Attachment #8535436 - Flags: approval-mozilla-beta+
Attachment #8535436 - Flags: approval-mozilla-aurora?
Attachment #8535436 - Flags: approval-mozilla-aurora+
https://hg.mozilla.org/releases/mozilla-aurora/rev/f74eb7dc50d5
https://hg.mozilla.org/releases/mozilla-beta/rev/0365c8a89b96
status-firefox35: affected → fixed
status-firefox36: affected → fixed

Updated

3 years ago
Attachment #8536742 - Flags: approval-mozilla-b2g34? → approval-mozilla-b2g34+
https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/e0431e466f13
status-b2g-v2.1: affected → fixed
You need to log in before you can comment on or make changes to this bug.