Closed Bug 1078017 Opened 10 years ago Closed 10 years ago

Intermittent test_ipc.html | test_peerConnection_basicAudioVideo.html,test_peerConnection_bug1013809.html,test_recordingStatus_kill_content_process.html - Assertion count 1 is greater than expected range (ASSERTION: track ended but not found)

Categories

(Core :: WebRTC, defect)

Product:
Core
Component:
WebRTC
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla36
Tracking Flags:
Tracking Status
firefox34 --- unaffected
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- unaffected
b2g-v2.0 --- unaffected
b2g-v2.0M --- unaffected
b2g-v2.1 --- unaffected
b2g-v2.2 --- fixed

People

(Reporter: philor, Assigned: pehrsons)

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(2 files)

Deregister track callbacks before unlinking tracks
4.27 KB, patch
jesup
: review+
jib
: review+
lmandel
: approval-mozilla-aurora+
Details | Diff | Splinter Review
modified patch to show differences better (NOT FOR CHECKIN)
2.17 KB, patch
Details | Diff | Splinter Review 
https://treeherder.mozilla.org/ui/logviewer.html#?job_id=591328&repo=b2g-inbound
builder 	Ubuntu VM 12.04 b2g-inbound debug test mochitest-3
buildid 	20141005095734
builduid 	f71f0f6951a14bdc9ed80722358b4d6e
results 	warnings (1)
revision 	644cb71aa537
slave 	tst-linux32-spot-047
starttime 	Sun Oct 05 2014 11:49:36 GMT-0700 (PDT)

11:55:14 INFO - [Child 1973] ###!!! ASSERTION: track ended but not found: 'Error', file /builds/slave/b2g-in-lx-d-000000000000000000/build/content/media/DOMMediaStream.cpp, line 86
11:55:48 INFO - mozilla::DOMMediaStream::StreamListener::TrackChange::Run() [content/media/DOMMediaStream.cpp:86]
11:55:48 INFO - nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:830]
11:55:48 INFO - NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:265]
11:55:48 INFO - mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:100]
11:55:48 INFO - MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:230]
11:55:48 INFO - MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:505]
11:55:48 INFO - nsBaseAppShell::Run() [widget/xpwidgets/nsBaseAppShell.cpp:166]
11:55:48 INFO - XRE_RunAppShell [toolkit/xre/nsEmbedFunctions.cpp:713]
11:55:48 INFO - mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:272]
11:55:48 INFO - MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:230]
11:55:48 INFO - MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:505]
11:55:48 INFO - XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:554]
11:55:48 INFO - content_process_main(int, char**) [ipc/contentproc/plugin-container.cpp:159]
11:55:48 INFO - main [ipc/app/MozillaRuntimeMain.cpp:12]
...
11:55:48 INFO - 231 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | test_peerConnection_basicAudioVideo.html - Assertion count 1 is greater than expected range 0-0 assertions.
OS: Mac OS X → Linux
Summary: Intermittent /test_ipc.html | test_peerConnection_basicAudioVideo.html - Assertion count 1 is greater than expected range 0-0 assertions from ASSERTION: track ended but not found → Intermittent /test_ipc.html | test_peerConnection_basicAudioVideo.html,test_peerConnection_bug1013809.html - Assertion count 1 is greater than expected range 0-0 assertions from ASSERTION: track ended but not found
Summary: Intermittent /test_ipc.html | test_peerConnection_basicAudioVideo.html,test_peerConnection_bug1013809.html - Assertion count 1 is greater than expected range 0-0 assertions from ASSERTION: track ended but not found → Intermittent test_ipc.html | test_peerConnection_basicAudioVideo.html,test_peerConnection_bug1013809.html,test_recordingStatus_kill_content_process.html - Assertion count 1 is greater than expected range (ASSERTION: track ended but not found)
I understand that Randell is busy with other things right now, but given the frequency we hit this and how widespread it is, can we please either find an owner with cycles to look into this or downgrade the assert to a warning?
Flags: needinfo?(mreavy)
I believe it happens when DOMMediaStream handles a TRACK_ENDED event in DOMMediaStream::StreamListener::TrackChange after having had DOMMediaStream.mTracks unlinked by the cycle collector.
See bug 1073406 comment 23. I made a patch that started hitting this bug a lot more often.

This patch fixes it per my previous comment by deregistering the streamlistener (listening for tracks created and ended) during unlinking.

It looks more messy than it is. I had to move the macros below the DOMMediaStream::StreamListener so that they know about DOMMediaStream::StreamListener::Forget().

I also had to expand NS_IMPL_CYCLE_COLLECTION_INHERITED per http://dxr.mozilla.org/mozilla-central/source/xpcom/glue/nsCycleCollectionParticipant.h#790 to manually deregister |mListener|.


Try before patch: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=cd2b6e1532bd (see linux debug M-3)

Try after patch: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=2cd2d2e353ab (triggering bug 1065924 (instead?) at some rate)

Try without other patches: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=d2226de2c105
Assignee: nobody → pehrsons
Status: NEW → ASSIGNED
Attachment #8516150 - Flags: review?(rjesup)
Note: won't compile due to forward references, but easier to see what changed.
Comment on attachment 8516150 [details] [diff] [review]
Deregister track callbacks before unlinking tracks

Review of attachment 8516150 [details] [diff] [review]:
-----------------------------------------------------------------

r+ but want jib to look too (alternate patch helps in reviewing, note Jan-Ivar)
Attachment #8516150 - Flags: review?(rjesup)
Attachment #8516150 - Flags: review?(jib)
Attachment #8516150 - Flags: review+
Thanks for Andreas (Pehrson) for the patch.  We'll work to get this fix landed this week.
Flags: needinfo?(mreavy)
Comment on attachment 8516150 [details] [diff] [review]
Deregister track callbacks before unlinking tracks

Review of attachment 8516150 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm.
Attachment #8516150 - Flags: review?(jib) → review+
Comment on attachment 8516150 [details] [diff] [review]
Deregister track callbacks before unlinking tracks

Review of attachment 8516150 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm.

::: dom/media/DOMMediaStream.cpp
@@ +99,5 @@
>    }
>  
>  private:
>    // These fields may only be accessed on the main thread
>    DOMMediaStream* mStream;

That said, whatever lifetime-rationale we had for using a raw pointer here seems flawed.

Why not make mStream an nsRefPtr instead of kludging cc unlink?
(In reply to Jan-Ivar Bruaroey [:jib] from comment #96)
> Comment on attachment 8516150 [details] [diff] [review]
> Deregister track callbacks before unlinking tracks
> 
> Review of attachment 8516150 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> lgtm.
> 
> ::: dom/media/DOMMediaStream.cpp
> @@ +99,5 @@
> >    }
> >  
> >  private:
> >    // These fields may only be accessed on the main thread
> >    DOMMediaStream* mStream;
> 
> That said, whatever lifetime-rationale we had for using a raw pointer here
> seems flawed.
> 
> Why not make mStream an nsRefPtr instead of kludging cc unlink?

Could you explain how making it an nsRefPtr would solve this bug? By also adding DOMMediaStream::mListener (and mListener->mStream) to CC?

I haven't fully wrapped my head around cycle collection yet..
Flags: needinfo?(jib)
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #97)
> > Why not make mStream an nsRefPtr instead of kludging cc unlink?
> 
> Could you explain how making it an nsRefPtr would solve this bug? By also
> adding DOMMediaStream::mListener (and mListener->mStream) to CC?

That's the direction I was thinking, but on further inspection I see that MediaStreamListener is used off-main-thread thus can't participate in cycle-collection, so nevermind.

> I haven't fully wrapped my head around cycle collection yet..

Me neither. I've heard it hurts when you do that.

Thanks for finding this! Looks good to go.
Flags: needinfo?(jib)
Yep, thanks guys!
https://hg.mozilla.org/mozilla-central/rev/1583a2e0c947
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
Please request Aurora and Beta approval for this when you get a chance.
status-b2g-v2.2: affected → fixed
status-firefox36: --- → fixed
Flags: needinfo?(pehrsons)
Comment on attachment 8516150 [details] [diff] [review]
Deregister track callbacks before unlinking tracks

Approval Request Comment
[Feature/regressing bug #]: bug 1077274 and the placeholder track landing

[User impact if declined]: Very annoyed sheriffs

[Describe test coverage new/current, TBPL]: well-covered by tests given the oranges

[Risks and why]: fairly low risk; touches the CC macros, but straightforward

[String/UUID change made/needed]: none
Attachment #8516150 - Flags: approval-mozilla-beta?
Attachment #8516150 - Flags: approval-mozilla-aurora?
Comment on attachment 8516150 [details] [diff] [review]
Deregister track callbacks before unlinking tracks

Beta+
Aurora+
Attachment #8516150 - Flags: approval-mozilla-beta?
Attachment #8516150 - Flags: approval-mozilla-beta+
Attachment #8516150 - Flags: approval-mozilla-aurora?
Attachment #8516150 - Flags: approval-mozilla-aurora+
https://hg.mozilla.org/releases/mozilla-aurora/rev/97102adbcc10

FF 34 isn't affected; it has tmp->Destroy() which was removed in 35 in bug 994912.  tmp->Destroy() gets rid of the listener and the stream.
Blocks: camera-events
status-firefox33: wontfix → ---
status-firefox34: affected → unaffected
status-firefox35: affected → fixed
Attachment #8516150 - Flags: approval-mozilla-beta+
status-b2g-v2.1: affected → unaffected
Flags: needinfo?(pehrsons)
I think these last ones are bug 1116925, which jesup is about to fix.

17:01:53 INFO - [Child 1930] ###!!! ASSERTION: Track not found: 'Error', file /builds/slave/m-cen-lx-d-0000000000000000000/build/src/dom/media/MediaStreamGraph.cpp, line 2452
17:01:53 INFO - #01: mozilla::SourceMediaStream::GetEndOfAppendedData(int) [dom/media/MediaStreamGraph.cpp:2452]
17:01:53 INFO - #02: mozilla::MediaEngineWebRTCVideoSource::NotifyPull(mozilla::MediaStreamGraph*, mozilla::SourceMediaStream*, int, long long) [dom/media/webrtc/MediaEngineWebRTCVideo.cpp:136]
17:01:53 INFO - #03: mozilla::GetUserMediaCallbackMediaStreamListener::NotifyPull(mozilla::MediaStreamGraph*, long long) [dom/media/MediaManager.h:191]
17:01:53 INFO - #04: mozilla::MediaStreamGraphImpl::ExtractPendingInput(mozilla::SourceMediaStream*, long long, bool*) [xpcom/glue/Mutex.h:206]
17:01:53 INFO - #05: mozilla::MediaStreamGraphImpl::UpdateGraph(long long) [dom/media/MediaStreamGraph.cpp:1276]
17:01:53 INFO - #06: mozilla::MediaStreamGraphImpl::OneIteration(long long, long long, long long, long long) [dom/media/MediaStreamGraph.cpp:1412]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: