Closed Bug 1357466 Opened 7 years ago Closed 7 years ago

Frequent shutdown crash following custom mochitest-media test run: ASSERTION: Mainthread not available

Categories

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

Product:
Core
Component:
Audio/Video: MediaStreamGraph
Type:
defect

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: gbrown, Assigned: jib)

References

Details

(Keywords: stale-bug) 

Bug 1339568 tracks an intermittent hang on shutdown seen in mochitest-media tests on Linux. That shutdown hang is relatively infrequent, but it has been happening for a long time and always happens in the mochitest-media suite after running tests in dom/media/tests/mochitest.

I pushed to try with some dom/media/tests/mochitest tests skipped and still reproduced the hang:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=82076cc5988c77c10a8525c93eb23579248568bf

Then I pushed to try again with additional dom/media/tests/mochitest tests skipped and hit a frequent intermittent crash during shutdown:

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

https://public-artifacts.taskcluster.net/MPvmFehSS9eWYjdmkE6Nbw/0/public/logs/live_backing.log

[task 2017-04-18T15:45:03.630531Z] 15:45:03     INFO - TEST-START | Shutdown
[task 2017-04-18T15:45:03.631363Z] 15:45:03     INFO - Passed:  813
[task 2017-04-18T15:45:03.631448Z] 15:45:03     INFO - Failed:  0
[task 2017-04-18T15:45:03.634338Z] 15:45:03     INFO - Todo:    110
[task 2017-04-18T15:45:03.635542Z] 15:45:03     INFO - Mode:    e10s
[task 2017-04-18T15:45:03.637127Z] 15:45:03     INFO - Slowest: 26523ms - /tests/dom/media/tests/mochitest/test_getUserMedia_mediaStreamClone.html
[task 2017-04-18T15:45:03.638318Z] 15:45:03     INFO - SimpleTest FINISHED
[task 2017-04-18T15:45:03.639412Z] 15:45:03     INFO - TEST-INFO | Ran 1 Loops
[task 2017-04-18T15:45:03.640499Z] 15:45:03     INFO - SimpleTest FINISHED
[task 2017-04-18T15:45:03.659083Z] 15:45:03     INFO - GECKO(3595) | ++DOMWINDOW == 9 (0x7fac438e5000) [pid = 3661] [serial = 55] [outer = 0x7fac45653000]
[task 2017-04-18T15:45:04.086028Z] 15:45:04     INFO - GECKO(3595) | --DOCSHELL 0x7f5f1b3c3800 == 3 [pid = 3595] [id = {923c07d0-f9a8-45cb-8052-1359553faba2}]
[task 2017-04-18T15:45:04.162875Z] 15:45:04     INFO - GECKO(3595) | --DOCSHELL 0x7f5f2631a800 == 2 [pid = 3595] [id = {521094d1-15b1-4ae9-9d84-55d1f72fe377}]
[task 2017-04-18T15:45:04.239367Z] 15:45:04     INFO - GECKO(3595) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2017-04-18T15:45:04.719970Z] 15:45:04     INFO - GECKO(3595) | --DOCSHELL 0x7f5f1b3c5800 == 1 [pid = 3595] [id = {78f5013b-cd47-46f5-9ed8-4a3019387713}]
[task 2017-04-18T15:45:04.720848Z] 15:45:04     INFO - GECKO(3595) | --DOCSHELL 0x7f5f22fcb800 == 0 [pid = 3595] [id = {13c2d214-283a-4df2-805a-1e8d5389fe18}]
[task 2017-04-18T15:45:04.721612Z] 15:45:04     INFO - GECKO(3595) | --DOMWINDOW == 13 (0x7f5f11caf800) [pid = 3595] [serial = 77] [outer = (nil)] [url = about:blank]
[task 2017-04-18T15:45:04.722513Z] 15:45:04     INFO - GECKO(3595) | --DOMWINDOW == 12 (0x7f5f195a7800) [pid = 3595] [serial = 79] [outer = (nil)] [url = about:blank]
[task 2017-04-18T15:45:04.723298Z] 15:45:04     INFO - GECKO(3595) | --DOMWINDOW == 11 (0x7f5f104c8000) [pid = 3595] [serial = 75] [outer = (nil)] [url = about:blank]
[task 2017-04-18T15:45:04.724150Z] 15:45:04     INFO - GECKO(3595) | --DOMWINDOW == 10 (0x7f5f104cc800) [pid = 3595] [serial = 73] [outer = (nil)] [url = about:blank]
[task 2017-04-18T15:45:05.352264Z] 15:45:05     INFO - GECKO(3595) | [Child 3661] WARNING: Late NotifyFinished after MediaManager shutdown: file /home/worker/workspace/build/src/dom/media/MediaManager.cpp, line 3669
[task 2017-04-18T15:45:05.724558Z] 15:45:05     INFO - GECKO(3595) | [Child 3661] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 1014
[task 2017-04-18T15:45:05.724686Z] 15:45:05     INFO - GECKO(3595) | [Child 3661] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 1014
[task 2017-04-18T15:45:05.727689Z] 15:45:05     INFO - GECKO(3595) | [Child 3661] WARNING: NS_ENSURE_TRUE(aObserver) failed: file /home/worker/workspace/build/src/modules/libpref/nsPrefBranch.cpp, line 745
[task 2017-04-18T15:45:05.728934Z] 15:45:05     INFO - GECKO(3595) | [Child 3661] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file /home/worker/workspace/build/src/modules/libpref/Preferences.cpp, line 1717
[task 2017-04-18T15:45:05.885759Z] 15:45:05     INFO - GECKO(3595) | --DOCSHELL 0x7fac438a8000 == 2 [pid = 3661] [id = {ce10d861-5ad5-47d8-ac22-374b583a2093}]
[task 2017-04-18T15:45:05.885868Z] 15:45:05     INFO - GECKO(3595) | --DOCSHELL 0x7fac58fd0800 == 1 [pid = 3661] [id = {3a082c13-3108-4885-9569-ae2964a654f4}]
[task 2017-04-18T15:45:05.969956Z] 15:45:05     INFO - GECKO(3595) | 1492530305968	Marionette	INFO	Ceased listening
[task 2017-04-18T15:45:06.106803Z] 15:45:06     INFO - GECKO(3595) | [Parent 3595] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file /home/worker/workspace/build/src/xpcom/threads/nsThread.cpp, line 1014
[task 2017-04-18T15:45:06.183082Z] 15:45:06     INFO - GECKO(3595) | [Parent 3595] WARNING: 'NS_FAILED(RemovePermissionChangeObserver())', file /home/worker/workspace/build/src/dom/notification/Notification.cpp, line 671
[task 2017-04-18T15:45:06.335514Z] 15:45:06     INFO - GECKO(3595) | [Child 3661] WARNING: '!mMainThread', file /home/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 314
[task 2017-04-18T15:45:06.335843Z] 15:45:06     INFO - GECKO(3595) | [Child 3661] WARNING: 'NS_FAILED(rv)', file /home/worker/workspace/build/src/dom/media/MediaManager.cpp, line 374
[task 2017-04-18T15:45:06.336689Z] 15:45:06     INFO - GECKO(3595) | [Child 3661] ###!!! ASSERTION: Mainthread not available; running on current thread: 'false', file /home/worker/workspace/build/src/dom/media/MediaManager.cpp, line 375
[task 2017-04-18T15:45:06.336853Z] 15:45:06     INFO - GECKO(3595) | #01: mozilla::MediaStream::RemoveAllListenersImpl [dom/media/MediaStreamGraph.cpp:2069]
[task 2017-04-18T15:45:06.337008Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.337113Z] 15:45:06     INFO - GECKO(3595) | #02: mozilla::MediaStream::Destroy()::Message::Run()
[task 2017-04-18T15:45:06.337628Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.339574Z] 15:45:06     INFO - GECKO(3595) | #03: mozilla::MediaStreamGraphImpl::AppendMessage [dom/media/MediaStreamGraph.cpp:1876]
[task 2017-04-18T15:45:06.340828Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.342130Z] 15:45:06     INFO - GECKO(3595) | #04: mozilla::MediaStream::Destroy [dom/media/MediaStreamGraph.cpp:2103]
[task 2017-04-18T15:45:06.343208Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.344793Z] 15:45:06     INFO - GECKO(3595) | #05: mozilla::DOMMediaStream::Destroy [dom/media/DOMMediaStream.cpp:474]
[task 2017-04-18T15:45:06.345905Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.346999Z] 15:45:06     INFO - GECKO(3595) | #06: mozilla::DOMMediaStream::cycleCollection::Unlink [dom/media/DOMMediaStream.cpp:357]
[task 2017-04-18T15:45:06.347615Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.348516Z] 15:45:06     INFO - GECKO(3595) | #07: nsCycleCollector::CollectWhite [xpcom/base/nsCycleCollector.cpp:3333]
[task 2017-04-18T15:45:06.350758Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.352966Z] 15:45:06     INFO - GECKO(3595) | #08: nsCycleCollector::Collect [xpcom/base/nsCycleCollector.cpp:3684]
[task 2017-04-18T15:45:06.355952Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.357178Z] 15:45:06     INFO - GECKO(3595) | #09: nsCycleCollector::ShutdownCollect [xpcom/base/nsCycleCollector.cpp:3602]
[task 2017-04-18T15:45:06.358860Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.361240Z] 15:45:06     INFO - GECKO(3595) | #10: nsCycleCollector_shutdown [mfbt/RefPtr.h:62]
[task 2017-04-18T15:45:06.362457Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.365547Z] 15:45:06     INFO - GECKO(3595) | #11: mozilla::ShutdownXPCOM [xpcom/build/XPCOMInit.cpp:992]
[task 2017-04-18T15:45:06.366769Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.368198Z] 15:45:06     INFO - GECKO(3595) | #12: XRE_TermEmbedding [toolkit/xre/nsEmbedFunctions.cpp:223]
[task 2017-04-18T15:45:06.369246Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.372506Z] 15:45:06     INFO - GECKO(3595) | #13: mozilla::ipc::ScopedXREEmbed::Stop [ipc/glue/ScopedXREEmbed.cpp:118]
[task 2017-04-18T15:45:06.373711Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.376134Z] 15:45:06     INFO - GECKO(3595) | #14: XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:704]
[task 2017-04-18T15:45:06.376245Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.377755Z] 15:45:06     INFO - GECKO(3595) | #15: content_process_main [ipc/contentproc/plugin-container.cpp:66]
[task 2017-04-18T15:45:06.377883Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.387687Z] 15:45:06     INFO - GECKO(3595) | #16: main [browser/app/nsBrowserApp.cpp:289]
[task 2017-04-18T15:45:06.389189Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.391643Z] 15:45:06     INFO - GECKO(3595) | #17: libc.so.6 + 0x20830
[task 2017-04-18T15:45:06.392712Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.393622Z] 15:45:06     INFO - GECKO(3595) | #18: _start
[task 2017-04-18T15:45:06.395090Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.399682Z] 15:45:06     INFO - GECKO(3595) | ###!!! [Child][MessageChannel] Error: (msgtype=0x4800C9,name=PContent::Msg_GraphicsError) Closed channel: cannot send/recv
[task 2017-04-18T15:45:06.400801Z] 15:45:06     INFO - GECKO(3595) | [Child 3661] WARNING: MsgDropped in ContentChild: file /home/worker/workspace/build/src/dom/ipc/ContentChild.cpp, line 2056
[task 2017-04-18T15:45:06.401972Z] 15:45:06     INFO - GECKO(3595) | [GFX1]: Texture deallocated too late during shutdown
[task 2017-04-18T15:45:06.403215Z] 15:45:06     INFO - GECKO(3595) | Assertion failure: [GFX1]: Texture deallocated too late during shutdown, at /home/worker/workspace/build/src/gfx/2d/Logging.h:519
[task 2017-04-18T15:45:06.404358Z] 15:45:06     INFO - GECKO(3595) | #01: mozilla::layers::DeallocateTextureClient [gfx/layers/client/TextureClient.cpp:325]
[task 2017-04-18T15:45:06.405381Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.406266Z] 15:45:06     INFO - GECKO(3595) | #02: mozilla::layers::TextureClient::Destroy [gfx/layers/client/TextureClient.cpp:422]
[task 2017-04-18T15:45:06.407637Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.409035Z] 15:45:06     INFO - GECKO(3595) | #03: mozilla::layers::TextureClient::~TextureClient [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.410396Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.411817Z] 15:45:06     INFO - GECKO(3595) | #04: mozilla::layers::TextureClient::~TextureClient [gfx/layers/client/TextureClient.cpp:603]
[task 2017-04-18T15:45:06.414233Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.415477Z] 15:45:06     INFO - GECKO(3595) | #05: mozilla::AtomicRefCountedWithFinalize<mozilla::layers::TextureClient>::Release [gfx/layers/AtomicRefCountedWithFinalize.h:138]
[task 2017-04-18T15:45:06.416508Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.417554Z] 15:45:06     INFO - GECKO(3595) | #06: mozilla::layers::TextureClientHolder::Release [memory/mozalloc/mozalloc.h:218]
[task 2017-04-18T15:45:06.419606Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.420790Z] 15:45:06     INFO - GECKO(3595) | #07: mozilla::layers::TextureClientRecycleAllocator::Destroy [gcc/include/c++/4.9.4/bits/stl_stack.h:218]
[task 2017-04-18T15:45:06.422065Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.423660Z] 15:45:06     INFO - GECKO(3595) | #08: mozilla::layers::CompositableClient::Destroy [gfx/layers/client/CompositableClient.cpp:85]
[task 2017-04-18T15:45:06.424805Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.426702Z] 15:45:06     INFO - GECKO(3595) | #09: mozilla::layers::CompositableClient::~CompositableClient [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.431501Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.432649Z] 15:45:06     INFO - GECKO(3595) | #10: mozilla::layers::ImageClientSingle::~ImageClientSingle [gfx/layers/client/ImageClient.h:85]
[task 2017-04-18T15:45:06.433193Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.434188Z] 15:45:06     INFO - GECKO(3595) | #11: mozilla::layers::CompositableClient::Release [gfx/layers/client/CompositableClient.h:75]
[task 2017-04-18T15:45:06.435098Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.435837Z] 15:45:06     INFO - GECKO(3595) | #12: mozilla::layers::ImageContainer::~ImageContainer [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.436407Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.437150Z] 15:45:06     INFO - GECKO(3595) | #13: RefPtr<mozilla::layers::ImageContainer>::~RefPtr [memory/mozalloc/mozalloc.h:218]
[task 2017-04-18T15:45:06.437682Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.438448Z] 15:45:06     INFO - GECKO(3595) | #14: mozilla::MediaEngineCameraVideoSource::~MediaEngineCameraVideoSource [dom/media/webrtc/MediaEngineCameraVideoSource.h:75]
[task 2017-04-18T15:45:06.439344Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.440919Z] 15:45:06     INFO - GECKO(3595) | #15: mozilla::MediaEngineRemoteVideoSource::~MediaEngineRemoteVideoSource [dom/media/webrtc/MediaEngineRemoteVideoSource.h:101]
[task 2017-04-18T15:45:06.441484Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.442379Z] 15:45:06     INFO - GECKO(3595) | #16: mozilla::MediaEngineRemoteVideoSource::Release [dom/media/webrtc/MediaEngineRemoteVideoSource.cpp:28]
[task 2017-04-18T15:45:06.446263Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.447231Z] 15:45:06     INFO - GECKO(3595) | #17: mozilla::MediaDevice::~MediaDevice [xpcom/string/nsTString.h:20]
[task 2017-04-18T15:45:06.447835Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.448604Z] 15:45:06     INFO - GECKO(3595) | #18: mozilla::VideoDevice::~VideoDevice [dom/media/MediaManager.h:113]
[task 2017-04-18T15:45:06.449197Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.450112Z] 15:45:06     INFO - GECKO(3595) | #19: mozilla::MediaDevice::Release [dom/media/MediaManager.cpp:688]
[task 2017-04-18T15:45:06.450943Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.451663Z] 15:45:06     INFO - GECKO(3595) | #20: mozilla::GetUserMediaCallbackMediaStreamListener::~GetUserMediaCallbackMediaStreamListener [dom/media/MediaManager.cpp:199]
[task 2017-04-18T15:45:06.452150Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.453001Z] 15:45:06     INFO - GECKO(3595) | #21: mozilla::GetUserMediaCallbackMediaStreamListener::~GetUserMediaCallbackMediaStreamListener [dom/media/MediaManager.cpp:203]
[task 2017-04-18T15:45:06.453511Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.455924Z] 15:45:06     INFO - GECKO(3595) | #22: mozilla::MediaStreamListener::Release [dom/media/MediaStreamListener.h:63]
[task 2017-04-18T15:45:06.456942Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.458036Z] 15:45:06     INFO - GECKO(3595) | #23: mozilla::MediaStream::RemoveAllListenersImpl [dom/media/MediaStreamGraph.cpp:2069]
[task 2017-04-18T15:45:06.459562Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.460667Z] 15:45:06     INFO - GECKO(3595) | #24: mozilla::MediaStream::Destroy()::Message::Run()
[task 2017-04-18T15:45:06.462101Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.463656Z] 15:45:06     INFO - GECKO(3595) | #25: mozilla::MediaStreamGraphImpl::AppendMessage [dom/media/MediaStreamGraph.cpp:1876]
[task 2017-04-18T15:45:06.464613Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.465283Z] 15:45:06     INFO - GECKO(3595) | #26: mozilla::MediaStream::Destroy [dom/media/MediaStreamGraph.cpp:2103]
[task 2017-04-18T15:45:06.465826Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.466679Z] 15:45:06     INFO - GECKO(3595) | #27: mozilla::DOMMediaStream::Destroy [dom/media/DOMMediaStream.cpp:474]
[task 2017-04-18T15:45:06.467182Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.468145Z] 15:45:06     INFO - GECKO(3595) | #28: mozilla::DOMMediaStream::cycleCollection::Unlink [dom/media/DOMMediaStream.cpp:357]
[task 2017-04-18T15:45:06.469611Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.470972Z] 15:45:06     INFO - GECKO(3595) | #29: nsCycleCollector::CollectWhite [xpcom/base/nsCycleCollector.cpp:3333]
[task 2017-04-18T15:45:06.472167Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.473499Z] 15:45:06     INFO - GECKO(3595) | #30: nsCycleCollector::Collect [xpcom/base/nsCycleCollector.cpp:3684]
[task 2017-04-18T15:45:06.474608Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.476186Z] 15:45:06     INFO - GECKO(3595) | #31: nsCycleCollector::ShutdownCollect [xpcom/base/nsCycleCollector.cpp:3602]
[task 2017-04-18T15:45:06.477511Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.483733Z] 15:45:06     INFO - GECKO(3595) | #32: nsCycleCollector_shutdown [mfbt/RefPtr.h:62]
[task 2017-04-18T15:45:06.484767Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.485657Z] 15:45:06     INFO - GECKO(3595) | #33: mozilla::ShutdownXPCOM [xpcom/build/XPCOMInit.cpp:992]
[task 2017-04-18T15:45:06.486644Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.487519Z] 15:45:06     INFO - GECKO(3595) | #34: XRE_TermEmbedding [toolkit/xre/nsEmbedFunctions.cpp:223]
[task 2017-04-18T15:45:06.488542Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.489436Z] 15:45:06     INFO - GECKO(3595) | #35: mozilla::ipc::ScopedXREEmbed::Stop [ipc/glue/ScopedXREEmbed.cpp:118]
[task 2017-04-18T15:45:06.490668Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.492034Z] 15:45:06     INFO - GECKO(3595) | #36: XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:704]
[task 2017-04-18T15:45:06.493427Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.495616Z] 15:45:06     INFO - GECKO(3595) | #37: content_process_main [ipc/contentproc/plugin-container.cpp:66]
[task 2017-04-18T15:45:06.496611Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.499581Z] 15:45:06     INFO - GECKO(3595) | #38: main [browser/app/nsBrowserApp.cpp:289]
[task 2017-04-18T15:45:06.500636Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.501528Z] 15:45:06     INFO - GECKO(3595) | #39: libc.so.6 + 0x20830
[task 2017-04-18T15:45:06.502534Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.503383Z] 15:45:06     INFO - GECKO(3595) | #40: _start
[task 2017-04-18T15:45:06.504418Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.505485Z] 15:45:06     INFO - GECKO(3595) | Hit MOZ_CRASH(GFX: An assert from the graphics logger) at /home/worker/workspace/build/src/gfx/2d/Logging.h:520
[task 2017-04-18T15:45:06.507001Z] 15:45:06     INFO - GECKO(3595) | #01: mozilla::layers::DeallocateTextureClient [gfx/layers/client/TextureClient.cpp:325]
[task 2017-04-18T15:45:06.508402Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.511644Z] 15:45:06     INFO - GECKO(3595) | #02: mozilla::layers::TextureClient::Destroy [gfx/layers/client/TextureClient.cpp:422]
[task 2017-04-18T15:45:06.512638Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.513554Z] 15:45:06     INFO - GECKO(3595) | #03: mozilla::layers::TextureClient::~TextureClient [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.514567Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.515429Z] 15:45:06     INFO - GECKO(3595) | #04: mozilla::layers::TextureClient::~TextureClient [gfx/layers/client/TextureClient.cpp:603]
[task 2017-04-18T15:45:06.516974Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.518438Z] 15:45:06     INFO - GECKO(3595) | #05: mozilla::AtomicRefCountedWithFinalize<mozilla::layers::TextureClient>::Release [gfx/layers/AtomicRefCountedWithFinalize.h:138]
[task 2017-04-18T15:45:06.519935Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.527142Z] 15:45:06     INFO - GECKO(3595) | #06: mozilla::layers::TextureClientHolder::Release [memory/mozalloc/mozalloc.h:218]
[task 2017-04-18T15:45:06.527590Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.527735Z] 15:45:06     INFO - GECKO(3595) | #07: mozilla::layers::TextureClientRecycleAllocator::Destroy [gcc/include/c++/4.9.4/bits/stl_stack.h:218]
[task 2017-04-18T15:45:06.528074Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.528424Z] 15:45:06     INFO - GECKO(3595) | #08: mozilla::layers::CompositableClient::Destroy [gfx/layers/client/CompositableClient.cpp:85]
[task 2017-04-18T15:45:06.528530Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.528745Z] 15:45:06     INFO - GECKO(3595) | #09: mozilla::layers::CompositableClient::~CompositableClient [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.528828Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.529008Z] 15:45:06     INFO - GECKO(3595) | #10: mozilla::layers::ImageClientSingle::~ImageClientSingle [gfx/layers/client/ImageClient.h:85]
[task 2017-04-18T15:45:06.529141Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.529343Z] 15:45:06     INFO - GECKO(3595) | #11: mozilla::layers::CompositableClient::Release [gfx/layers/client/CompositableClient.h:75]
[task 2017-04-18T15:45:06.532939Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.533004Z] 15:45:06     INFO - GECKO(3595) | #12: mozilla::layers::ImageContainer::~ImageContainer [mfbt/RefPtr.h:77]
[task 2017-04-18T15:45:06.533032Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.533092Z] 15:45:06     INFO - GECKO(3595) | #13: RefPtr<mozilla::layers::ImageContainer>::~RefPtr [memory/mozalloc/mozalloc.h:218]
[task 2017-04-18T15:45:06.533119Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.533418Z] 15:45:06     INFO - GECKO(3595) | #14: mozilla::MediaEngineCameraVideoSource::~MediaEngineCameraVideoSource [dom/media/webrtc/MediaEngineCameraVideoSource.h:75]
[task 2017-04-18T15:45:06.534310Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.534398Z] 15:45:06     INFO - GECKO(3595) | #15: mozilla::MediaEngineRemoteVideoSource::~MediaEngineRemoteVideoSource [dom/media/webrtc/MediaEngineRemoteVideoSource.h:101]
[task 2017-04-18T15:45:06.534426Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.534709Z] 15:45:06     INFO - GECKO(3595) | #16: mozilla::MediaEngineRemoteVideoSource::Release [dom/media/webrtc/MediaEngineRemoteVideoSource.cpp:28]
[task 2017-04-18T15:45:06.537209Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.537274Z] 15:45:06     INFO - GECKO(3595) | #17: mozilla::MediaDevice::~MediaDevice [xpcom/string/nsTString.h:20]
[task 2017-04-18T15:45:06.539697Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.540136Z] 15:45:06     INFO - GECKO(3595) | #18: mozilla::VideoDevice::~VideoDevice [dom/media/MediaManager.h:113]
[task 2017-04-18T15:45:06.540400Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.540825Z] 15:45:06     INFO - GECKO(3595) | #19: mozilla::MediaDevice::Release [dom/media/MediaManager.cpp:688]
[task 2017-04-18T15:45:06.541142Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.541604Z] 15:45:06     INFO - GECKO(3595) | #20: mozilla::GetUserMediaCallbackMediaStreamListener::~GetUserMediaCallbackMediaStreamListener [dom/media/MediaManager.cpp:199]
[task 2017-04-18T15:45:06.543451Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.545125Z] 15:45:06     INFO - GECKO(3595) | #21: mozilla::GetUserMediaCallbackMediaStreamListener::~GetUserMediaCallbackMediaStreamListener [dom/media/MediaManager.cpp:203]
[task 2017-04-18T15:45:06.546508Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.548101Z] 15:45:06     INFO - GECKO(3595) | #22: mozilla::MediaStreamListener::Release [dom/media/MediaStreamListener.h:63]
[task 2017-04-18T15:45:06.549356Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.550934Z] 15:45:06     INFO - GECKO(3595) | #23: mozilla::MediaStream::RemoveAllListenersImpl [dom/media/MediaStreamGraph.cpp:2069]
[task 2017-04-18T15:45:06.552418Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.553956Z] 15:45:06     INFO - GECKO(3595) | #24: mozilla::MediaStream::Destroy()::Message::Run()
[task 2017-04-18T15:45:06.555177Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.556766Z] 15:45:06     INFO - GECKO(3595) | #25: mozilla::MediaStreamGraphImpl::AppendMessage [dom/media/MediaStreamGraph.cpp:1876]
[task 2017-04-18T15:45:06.558005Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.559621Z] 15:45:06     INFO - GECKO(3595) | #26: mozilla::MediaStream::Destroy [dom/media/MediaStreamGraph.cpp:2103]
[task 2017-04-18T15:45:06.561076Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.562464Z] 15:45:06     INFO - GECKO(3595) | #27: mozilla::DOMMediaStream::Destroy [dom/media/DOMMediaStream.cpp:474]
[task 2017-04-18T15:45:06.563896Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.565494Z] 15:45:06     INFO - GECKO(3595) | #28: mozilla::DOMMediaStream::cycleCollection::Unlink [dom/media/DOMMediaStream.cpp:357]
[task 2017-04-18T15:45:06.566739Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.568454Z] 15:45:06     INFO - GECKO(3595) | #29: nsCycleCollector::CollectWhite [xpcom/base/nsCycleCollector.cpp:3333]
[task 2017-04-18T15:45:06.569739Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.571329Z] 15:45:06     INFO - GECKO(3595) | #30: nsCycleCollector::Collect [xpcom/base/nsCycleCollector.cpp:3684]
[task 2017-04-18T15:45:06.572783Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.574237Z] 15:45:06     INFO - GECKO(3595) | #31: nsCycleCollector::ShutdownCollect [xpcom/base/nsCycleCollector.cpp:3602]
[task 2017-04-18T15:45:06.575703Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.577284Z] 15:45:06     INFO - GECKO(3595) | #32: nsCycleCollector_shutdown [mfbt/RefPtr.h:62]
[task 2017-04-18T15:45:06.580354Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.580487Z] 15:45:06     INFO - GECKO(3595) | #33: mozilla::ShutdownXPCOM [xpcom/build/XPCOMInit.cpp:992]
[task 2017-04-18T15:45:06.580517Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.581987Z] 15:45:06     INFO - GECKO(3595) | #34: XRE_TermEmbedding [toolkit/xre/nsEmbedFunctions.cpp:223]
[task 2017-04-18T15:45:06.583237Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.584824Z] 15:45:06     INFO - GECKO(3595) | #35: mozilla::ipc::ScopedXREEmbed::Stop [ipc/glue/ScopedXREEmbed.cpp:118]
[task 2017-04-18T15:45:06.587434Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.587516Z] 15:45:06     INFO - GECKO(3595) | #36: XRE_InitChildProcess [toolkit/xre/nsEmbedFunctions.cpp:704]
[task 2017-04-18T15:45:06.588922Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.590652Z] 15:45:06     INFO - GECKO(3595) | #37: content_process_main [ipc/contentproc/plugin-container.cpp:66]
[task 2017-04-18T15:45:06.590722Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.594773Z] 15:45:06     INFO - GECKO(3595) | #38: main [browser/app/nsBrowserApp.cpp:289]
[task 2017-04-18T15:45:06.594809Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.594847Z] 15:45:06     INFO - GECKO(3595) | #39: libc.so.6 + 0x20830
[task 2017-04-18T15:45:06.594871Z] 15:45:06     INFO - 
[task 2017-04-18T15:45:06.597058Z] 15:45:06     INFO - GECKO(3595) | #40: _start
[task 2017-04-18T15:45:06.597093Z] 15:45:06     INFO -
We are hitting an assertion at https://dxr.mozilla.org/mozilla-central/rev/a374c35469935a874fefe64d3e07003fc5bc8884/dom/media/MediaManager.cpp#375.
Component: General → Audio/Video
Product: Testing → Core
Summary: Shutdown crash following custom mochitest-media test run: ASSERTION: Mainthread not available → Frequent shutdown crash following custom mochitest-media test run: ASSERTION: Mainthread not available
Rank: 29
Priority: -- → P2
Component: Audio/Video → Audio/Video: MediaStreamGraph
This is during the shutdown of the process. If we can detect that this is the case, we can relax the assertion.
:padenot, is this something you can look at?
Flags: needinfo?(padenot)
jib, we need to destroy `GetUserMediaCallbackMediaStreamListener` earlier in shutdown to not crash, or at least, drop all textures.

What would be best to do here? I'm thinking either:
- using the observer service to hook up destroying everything related to `getUserMedia` calls earlier
- trashing `DOMMediaStream` on documents close (more aggressively) instead of relying on the CC
- maybe something else ?
Flags: needinfo?(padenot) → needinfo?(jib)
I don't think the bug is that a GetUserMediaCallbackMediaStreamListener exists this late, but rather that it hasn't had Remove() called on it when it should have.

Basically, mozilla::MediaStream::RemoveAllListenersImpl above should never find any added listeners this late, and then we're ok.

Oddly, we ARE mass-Remove()ing them on shutdown, here:

> Thread 1Queue : com.apple.main-thread (serial)
> #0	0x00000001061160d4 in mozilla::GetUserMediaCallbackMediaStreamListener::Remove() at /Users/Jan/moz/mozilla-central/dom/media/MediaManager.cpp:323
> #1	0x00000001061158fc in mozilla::StopSharingCallback(mozilla::MediaManager*, unsigned long long, nsTArray<RefPtr<mozilla::GetUserMediaCallbackMediaStreamListener> >*, void*) at /Users/Jan/moz/mozilla-central/dom/media/MediaManager.cpp:2661
> #2	0x000000010611567d in mozilla::MediaManager::IterateWindowListeners(nsPIDOMWindowInner*, void (*)(mozilla::MediaManager*, unsigned long long, nsTArray<RefPtr<mozilla::GetUserMediaCallbackMediaStreamListener> >*, void*), void*) at /Users/Jan/moz/mozilla-central/dom/media/MediaManager.cpp:3333
> #3	0x00000001061155bb in mozilla::MediaManager::OnNavigation(unsigned long long) at /Users/Jan/moz/mozilla-central/dom/media/MediaManager.cpp:2691
> #4	0x00000001047bbfb4 in mozilla::dom::Navigator::OnNavigation() at /Users/Jan/moz/mozilla-central/dom/base/Navigator.cpp:1661
> #5	0x00000001046869d7 in nsGlobalWindow::FreeInnerObjects() at /Users/Jan/moz/mozilla-central/dom/base/nsGlobalWindow.cpp:2074
> #6	0x000000010469196a in nsGlobalWindow::DetachFromDocShell() at /Users/Jan/moz/mozilla-central/dom/base/nsGlobalWindow.cpp:3478
> #7	0x0000000108eccb73 in nsDocShell::Destroy() at /Users/Jan/moz/mozilla-central/docshell/base/nsDocShell.cpp:5876

So somewhere there's a stray active GetUserMediaCallbackMediaStreamListener.

Could we instrument RemoveAllListenersImpl to yell if the list of listeners is non-empty on shutdown, and rat out which one it is / where it came from?
Flags: needinfo?(jib)
s/So/Yet/
Is this e10s only? (sorry none of the log links appear to work for me today. Infra problem?)
Assignee: nobody → jib
Rank: 29 → 16
Priority: P2 → P1
This is an assigned P1 bug without activity in two weeks. 

If you intend to continue working on this bug for the current release/iteration/sprint, remove the 'stale-bug' keyword.

Otherwise we'll reset the priority of the bug back to '--' on Monday, August 28th.
Keywords: stale-bug
Mass change P1->P2 to align with new Mozilla triage process
Priority: P1 → P2
:jib, are there any plans to fix this?
Flags: needinfo?(jib)
Andreas, do we think this is fixed by/related to bug 1407542?
Flags: needinfo?(jib) → needinfo?(apehrson)
I think this was fixed by bug 1320994; if not it should have been fixed by bug 1410829.
Blocks: 1320994, 1410829
Status: NEW → RESOLVED
Closed: 7 years ago
Flags: needinfo?(apehrson)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.