Closed Bug 1109405 Opened 10 years ago Closed 10 years ago

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

Categories

(Core :: WebRTC: Audio/Video, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla37
Tracking Status
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

People

(Reporter: pehrsons, Assigned: pehrsons)

References

Details

Attachments

(2 files, 2 obsolete files)

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
Blocks: 1073406
Assignee: nobody → pehrsons
Status: NEW → ASSIGNED
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: MediaSegmentBase
(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
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.
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]
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
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
That didn't do it. My bad, too naive - probably fails when the input track is blocked.
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?
(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...
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.
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
(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
I also take it as likely that this was causing the failures on bug 991273. We could try to revert it.
No longer depends on: MediaSegmentBase
(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.
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)
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.
Stuff is happening in bug 1073772 apparently. Let's see what they say over there.
Attachment #8535436 - Flags: review?(rjesup) → review+
Attachment #8535449 - Attachment is obsolete: true
Attachment #8535449 - Flags: review?(padenot)
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
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
Closed: 10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
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?
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.
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+
Attachment #8536742 - Flags: approval-mozilla-b2g34? → approval-mozilla-b2g34+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: