Closed Bug 1032011 Opened 10 years ago Closed 10 years ago

Intermittent B2G debug mochitest-9,12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380"

Categories

(Core :: DOM: Workers, defect)

Product:
Core
Component:
DOM: Workers
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla33
Tracking Flags:
Tracking Status
firefox31 --- unaffected
firefox32 --- unaffected
firefox33 --- fixed
firefox-esr24 --- unaffected
b2g-v1.4 --- unaffected
b2g-v2.0 --- unaffected
b2g-v2.1 --- fixed

People

(Reporter: nigelb, Assigned: bkelly)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 7 obsolete files)

Handle async ActorDestroy() callback when closing PBackground. (v7)
12.93 KB, patch
Details | Diff | Splinter Review
Not sure if DOM is right place or this needs to go into Firefox OS b2g_emulator_vm b2g-inbound debug test mochitest-debug-12 on 2014-06-28 22:24:35 PDT for push 5a63232687d1 slave: tst-linux64-spot-609 https://tbpl.mozilla.org/php/getParsedLog.php?id=42710769&tree=B2g-Inbound 22:39:49 INFO - 06-29 05:37:42.646 730 730 I Gecko : [Child 730] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947 22:39:49 INFO - 06-29 05:37:49.546 730 730 I Gecko : --DOMWINDOW == 2 (0x4408fad0) [pid = 730] [serial = 2] [outer = 0x4408f730] [url = about:blank] 22:39:49 INFO - 06-29 05:37:52.125 656 656 I Gecko : [Parent 656] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2256 22:39:49 INFO - 06-29 05:37:52.155 656 656 I Gecko : [Parent 656] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2256 22:39:49 INFO - 06-29 05:37:52.155 656 656 I Gecko : [Parent 656] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2256 22:39:49 INFO - 06-29 05:37:52.155 656 656 I Gecko : [Parent 656] WARNING: A control runnable was posted to a worker that is already shutting down!: file ../../../gecko/dom/workers/WorkerPrivate.cpp, line 2256 22:39:49 INFO - 06-29 05:37:52.596 730 730 I Gecko : [Child 730] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 238 22:39:49 INFO - 06-29 05:37:52.676 730 730 I Gecko : [Child 730] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../gecko/dom/xbl/nsXBLDocumentInfo.cpp, line 306 22:39:49 INFO - 06-29 05:37:52.785 730 730 I Gecko : ++DOCSHELL 0x440d0000 == 2 [pid = 730] [id = 2] 22:39:49 INFO - 06-29 05:37:52.795 730 730 I Gecko : ++DOMWINDOW == 3 (0x4408fad0) [pid = 730] [serial = 4] [outer = 0x0] 22:39:49 INFO - 06-29 05:37:52.835 730 730 I Gecko : [Child 730] WARNING: NS_ENSURE_TRUE(nsContentUtils::GetCurrentJSContext()) failed: file ../../../gecko/docshell/base/nsDocShell.cpp, line 8693 22:39:49 INFO - 06-29 05:37:53.636 730 730 I Gecko : [Child 730] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file ../../../../../gecko/content/html/document/src/nsHTMLContentSink.cpp, line 741 22:39:49 INFO - 06-29 05:37:53.686 730 730 I Gecko : ++DOMWINDOW == 4 (0x44090210) [pid = 730] [serial = 5] [outer = 0x4408fad0] 22:39:49 INFO - 06-29 05:37:54.195 730 730 E GeckoConsole: [JavaScript Warning: "No meta-viewport tag found. Please explicitly specify one to prevent unexpected behavioural changes in future versions. For more help https://developer.mozilla.org/en/docs/Mozilla/Mobile/Viewport_meta_tag" {file: "http://mochi.test:8888/tests/?autorun=1&timeout=420&closeWhenDone=1&logFile=%2Fdata%2Flocal%2Ftests%2Flog%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&totalChunks=15&thisChunk=12&hideResultsTable=1&dumpOutputDirectory=%2Ftmp&quiet=true&manifestFile=tests.json" line: 0}] 22:39:49 INFO - 06-29 05:37:55.045 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:37:55.326 656 731 D : HostConnection::get() New Host Connection established 0x476b0f80, tid 731 22:39:49 INFO - 06-29 05:37:55.406 730 744 D : HostConnection::get() New Host Connection established 0x44a51c40, tid 744 22:39:49 INFO - 06-29 05:37:55.476 730 730 D : HostConnection::get() New Host Connection established 0x44a51c80, tid 730 22:39:49 INFO - 06-29 05:37:59.496 730 730 I GeckoDump: 0 INFO Running tests 1589-1733/2166 22:39:49 INFO - 06-29 05:37:59.516 730 730 I GeckoDump: 1 INFO SimpleTest START 22:39:49 INFO - 06-29 05:37:59.915 730 730 I GeckoDump: 2 INFO TEST-START | /tests/dom/workers/test/test_bug1002702.html 22:39:49 INFO - 06-29 05:37:59.955 730 730 I Gecko : [Child 730] WARNING: TabChild::SetFocus not supported in TabChild: file ../../../gecko/dom/ipc/TabChild.cpp, line 1137 22:39:49 INFO - 06-29 05:38:00.145 656 656 I Gecko : [Parent 656] WARNING: No docshells for remote frames!: file ../../../../gecko/content/base/src/nsFrameLoader.cpp, line 631 22:39:49 INFO - 06-29 05:38:00.316 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:01.576 730 730 I Gecko : ++DOMWINDOW == 5 (0x440903e0) [pid = 730] [serial = 6] [outer = 0x4408fad0] 22:39:49 INFO - 06-29 05:38:02.726 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:03.296 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:03.965 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:04.245 730 730 I Gecko : ++DOMWINDOW == 6 (0x440905b0) [pid = 730] [serial = 7] [outer = 0x4408fad0] 22:39:49 INFO - 06-29 05:38:04.825 730 730 I Gecko : [Child 730] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947 22:39:49 INFO - 06-29 05:38:05.165 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:06.295 730 730 I Gecko : [Child 730] WARNING: Called close() before start()!: 'mStarted', file ../../../gecko/dom/workers/MessagePort.cpp, line 214 22:39:49 INFO - 06-29 05:38:09.286 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:09.396 730 730 E GeckoConsole: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/workers/test/test_bug1002702.html" line: 0}] 22:39:49 INFO - 06-29 05:38:09.427 730 730 I Gecko : [Child 730] WARNING: Unable to printf the requested string due to error.: file ../../../gecko/ipc/chromium/src/base/string_util.cc, line 427 22:39:49 INFO - 06-29 05:38:09.676 730 730 I Gecko : [Child 730] WARNING: Transparent content with displayports can be expensive.: file ../../../gecko/layout/base/nsDisplayList.cpp, line 1371 22:39:49 INFO - 06-29 05:38:11.706 730 730 I GeckoDump: 3 INFO TEST-INFO | MEMORY STAT vsize after test: 99393536 22:39:49 INFO - 06-29 05:38:11.815 730 730 I GeckoDump: 4 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. 22:39:49 INFO - 06-29 05:38:12.045 730 730 I GeckoDump: 5 INFO TEST-INFO | MEMORY STAT residentFast after test: 49848320 22:39:49 INFO - 06-29 05:38:12.225 730 730 I GeckoDump: 6 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 15230480 22:39:49 INFO - 06-29 05:38:12.415 730 749 F MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ../../../gecko/ipc/glue/BackgroundImpl.cpp:380 22:39:49 INFO - 06-29 05:38:14.376 656 668 I Gecko : [Parent 656] WARNING: pipe error (80): Connection reset by peer: file ../../../gecko/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 450 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.115 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.125 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : ###!!! [Parent][OnMaybeDequeueOne] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.135 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.145 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.145 656 656 I Gecko : ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv 22:39:49 INFO - 06-29 05:38:15.145 656 656 I Gecko : 22:39:49 INFO - 06-29 05:38:15.276 656 656 I Gecko : ############ ErrorPage.js 22:39:49 INFO - 06-29 05:38:15.336 656 656 I Gecko : [Parent 656] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204 22:39:49 INFO - 06-29 05:38:15.347 656 656 I Gecko : [Parent 656] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204 22:39:49 INFO - 06-29 05:38:15.347 656 656 I Gecko : [Parent 656] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204 22:39:49 INFO - 06-29 05:38:15.347 656 656 I Gecko : [Parent 656] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204 22:39:49 INFO - 06-29 05:38:15.347 656 656 I Gecko : [Parent 656] WARNING: RemoveObserver() called for unregistered observer: file ../../gecko/hal/Hal.cpp, line 204 22:39:49 INFO - 06-29 05:38:15.526 40 40 D AudioHardwareInterface: setMode(NORMAL) 22:39:49 INFO - 06-29 05:38:15.526 40 40 W AudioPolicyManagerBase: setPhoneState() setting same state 0 22:39:49 INFO - 06-29 05:38:15.546 656 656 I Gecko : [Parent 656] WARNING: NS_ENSURE_TRUE(mCallback) failed: file ../../../../gecko/content/base/src/nsFrameMessageManager.cpp, line 671 22:39:49 WARNING - 06-29 05:38:15.576 656 656 E GeckoConsole: [JavaScript Error: "NS_ERROR_NOT_INITIALIZED: Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]" {file: "chrome://specialpowers/content/SpecialPowersObserver.js" line: 96}] 22:39:49 INFO - 06-29 05:38:15.676 656 656 I Gecko : [Parent 656] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file ../../../gecko/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 20 22:39:49 INFO - 06-29 05:38:15.835 656 656 I Gecko : [Parent 656] WARNING: NS_ENSURE_TRUE(mCallback) failed: file ../../../../gecko/content/base/src/nsFrameMessageManager.cpp, line 671 22:39:49 INFO - 06-29 05:38:15.865 656 656 I Gecko : [Parent 656] WARNING: NS_ENSURE_TRUE(mCallback) failed: file ../../../../gecko/content/base/src/nsFrameMessageManager.cpp, line 671 22:39:49 INFO - 06-29 05:38:16.025 656 656 I Gecko : --DOCSHELL 0x47d4e000 == 1 [pid = 656] [id = 2] 22:39:49 INFO - 06-29 05:38:16.045 656 656 I Gecko : --DOCSHELL 0x45921400 == 0 [pid = 656] [id = 1] 22:39:49 INFO - 06-29 05:38:16.396 656 656 I Gecko : [Parent 656] WARNING: An event was posted to a thread that will never run it (rejected): file ../../../gecko/xpcom/threads/nsThread.cpp, line 462 22:39:49 INFO - 06-29 05:38:16.396 656 656 I Gecko : [Parent 656] WARNING: unable to post continuation event: file ../../../gecko/xpcom/io/nsStreamUtils.cpp, line 455 22:39:49 INFO - 06-29 05:38:21.805 656 688 I Gecko : Destroying context 0x477c6880 surface 0x477c6850 on display 0x1 22:39:49 INFO - 06-29 05:38:22.426 656 656 I Gecko : -*- NetworkService: NetworkService shutdown 22:39:49 INFO - 06-29 05:38:22.915 656 656 I Gecko : [Parent 656] WARNING: Disconnect: No ongoing file transfer to stop: file ../../../gecko/dom/bluetooth/bluez/BluetoothOppManager.cpp, line 1537 22:39:49 INFO - 06-29 05:38:22.935 656 656 I Gecko : [Parent 656] WARNING: SCO has been already disconnected.: file ../../../gecko/dom/bluetooth/bluez/BluetoothHfpManager.cpp, line 1965 22:39:49 INFO - 06-29 05:38:23.696 656 656 I Gonk : RIL[0]: OnDisconnect 22:39:49 INFO - 06-29 05:38:23.765 656 656 I GonkMemoryPressure: Observed XPCOM shutdown. 22:39:49 INFO - 06-29 05:38:25.125 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.125 656 656 I Gecko : [Parent 656] WARNING: Failed to remove shutdown observer!: file ../../../gecko/dom/bluetooth/bluez/BluetoothOppManager.cpp, line 213 22:39:49 INFO - 06-29 05:38:25.125 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.125 656 656 I Gecko : [Parent 656] WARNING: Failed to remove shutdown observer!: file ../../../gecko/dom/bluetooth/bluez/BluetoothA2dpManager.cpp, line 79 22:39:49 INFO - 06-29 05:38:25.135 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.135 656 656 I Gecko : [Parent 656] WARNING: Failed to remove shutdown observer!: file ../../../gecko/dom/bluetooth/BluetoothHidManager.cpp, line 77 22:39:49 INFO - 06-29 05:38:25.145 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.165 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.165 656 656 I Gecko : [Parent 656] WARNING: Failed to remove observers!: file ../../../gecko/dom/bluetooth/bluez/BluetoothHfpManager.cpp, line 479 22:39:49 INFO - 06-29 05:38:25.185 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Using observer service after XPCOM shutdown!: 'Error', file ../../../gecko/xpcom/ds/nsObserverService.cpp, line 261 22:39:49 INFO - 06-29 05:38:25.205 656 656 I Gecko : [Parent 656] WARNING: NS_ENSURE_TRUE(obs) failed: file ../../../../gecko/dom/system/gonk/AudioManager.cpp, line 484 22:39:49 INFO - 06-29 05:38:31.466 656 656 I Gecko : [Parent 656] WARNING: unable to Flush() dirty datasource during XPCOM shutdown: file ../../../../gecko/rdf/base/src/nsRDFXMLDataSource.cpp, line 747 22:39:49 INFO - 06-29 05:38:39.475 656 656 I Gecko : --DOMWINDOW == 3 (0x49251a80) [pid = 656] [serial = 5] [outer = 0x0] [url = app://test-container.gaiamobile.org/index.html] 22:39:49 INFO - 06-29 05:38:39.486 656 656 I Gecko : --DOMWINDOW == 2 (0x4459c520) [pid = 656] [serial = 3] [outer = 0x0] [url = app://test-container.gaiamobile.org/index.html] 22:39:49 INFO - 06-29 05:38:42.145 656 656 I Gecko : [Parent 656] WARNING: Leaking the RDF Service.: file ../../../gecko/rdf/build/nsRDFModule.cpp, line 165 22:39:49 INFO - 06-29 05:38:42.205 656 656 I Gecko : [Parent 656] ###!!! ASSERTION: Component Manager being held past XPCOM shutdown.: 'cnt == 0', file ../../../gecko/xpcom/build/nsXPComInit.cpp, line 957 22:39:49 INFO - 06-29 05:38:42.205 656 656 I Gecko : [Parent 656] WARNING: '!compMgr', file /builds/slave/b2g_b2g-in_emu-d_dep-000000000/build/gecko/xpcom/glue/nsComponentManagerUtils.cpp, line 62 22:39:49 INFO - 06-29 05:38:42.298 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.298 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.305 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.305 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.305 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.305 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.326 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.326 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.336 656 656 I Gecko : [Parent 656] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file ../../../gecko/xpcom/base/nsTraceRefcnt.cpp, line 144 22:39:49 INFO - 06-29 05:38:42.436 33 33 I ServiceManager: service 'media.resource_manager' died 22:39:49 INFO - 06-29 05:38:42.436 33 33 I ServiceManager: service 'permission' died 22:39:49 INFO - Return code: 0 22:39:49 INFO - Running command: ['ps', '-C', 'emulator'] 22:39:49 INFO - Copy/paste: ps -C emulator 22:39:49 INFO - PID TTY TIME CMD 22:39:49 ERROR - Return code: 1 22:39:49 INFO - Running command: ['/builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb', 'devices'] 22:39:49 INFO - Copy/paste: /builds/slave/test/build/emulator/b2g-distro/out/host/linux-x86/bin/adb devices 22:39:49 INFO - List of devices attached 22:39:49 INFO - Return code: 0 22:39:49 INFO - Copying /builds/slave/test/build/emulator-5554.log to /builds/slave/test/build/blobber_upload_dir/emulator-5554.log 22:39:49 INFO - Copying /builds/slave/test/build/qemu.log to /builds/slave/test/build/blobber_upload_dir/qemu.log 22:39:49 INFO - TinderboxPrint: mochitest<br/><em class="testfail">T-FAIL</em> 22:39:49 WARNING - # TBPL WARNING # 22:39:49 WARNING - The mochitest suite: mochitest-12 ran with return status: WARNING 22:39:49 INFO - Running post-action listener: _resource_record_post_action 22:39:49 INFO - Running post-run listener: _resource_record_post_run 22:39:50 INFO - Total resource usage - Wall time: 835s; CPU: 92.0%; Read bytes: 34938880; Write bytes: 190173184; Read time: 7232; Write time: 392476 22:39:50 INFO - install - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0 22:39:50 INFO - run-tests - Wall time: 835s; CPU: 92.0%; Read bytes: 30986240; Write bytes: 189534208; Read time: 6964; Write time: 392400 22:39:50 INFO - Running post-run listener: _upload_blobber_files 22:39:50 INFO - Blob upload gear active. 22:39:50 INFO - Preparing to upload files from /builds/slave/test/build/blobber_upload_dir. 22:39:50 INFO - Files from /builds/slave/test/build/blobber_upload_dir are to be uploaded with <b2g-inbound> branch at the following location(s): https://blobupload.elasticbeanstalk.com 22:39:50 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/venv/bin/blobberc.py', '-u', 'https://blobupload.elasticbeanstalk.com', '-a', '/builds/slave/test/oauth.txt', '-b', 'b2g-inbound', '-d', '/builds/slave/test/build/blobber_upload_dir'] 22:39:50 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python /builds/slave/test/build/venv/bin/blobberc.py -u https://blobupload.elasticbeanstalk.com -a /builds/slave/test/oauth.txt -b b2g-inbound -d /builds/slave/test/build/blobber_upload_dir 22:39:51 INFO - (blobuploader) - INFO - Open directory for files ... 22:39:51 INFO - (blobuploader) - INFO - Uploading /builds/slave/test/build/blobber_upload_dir/qemu.log ... 22:39:51 INFO - (blobuploader) - INFO - Using https://blobupload.elasticbeanstalk.com 22:39:51 INFO - (blobuploader) - INFO - Uploading, attempt #1. 22:39:52 INFO - (blobuploader) - INFO - TinderboxPrint: <a href='http://mozilla-releng-blobs.s3.amazonaws.com/blobs/b2g-inbound/sha512/bd3f49cec0f3bce15a2351853361ab283ca9a0aa6d26d3d3b9ff179e429d629ea81f07102fc935bfaf9d13c9b8842a4c9c79cd84ced250536c8a997fdbf95dbc'>qemu.log</a>: uploaded 22:39:52 INFO - (blobuploader) - INFO - Blobserver returned 202. File uploaded! 22:39:52 INFO - (blobuploader) - INFO - Done attempting. 22:39:52 INFO - (blobuploader) - INFO - Uploading /builds/slave/test/build/blobber_upload_dir/emulator-5554.log ... 22:39:52 INFO - (blobuploader) - INFO - Using https://blobupload.elasticbeanstalk.com 22:39:52 INFO - (blobuploader) - INFO - Uploading, attempt #1. 22:39:53 INFO - (blobuploader) - INFO - TinderboxPrint: <a href='http://mozilla-releng-blobs.s3.amazonaws.com/blobs/b2g-inbound/sha512/b58e70108a2bcce6c5185e92ad4bcc25f1dedbc4814f8458630b68f68c1f34c1c9097b58253a4688afd9a5610bab1f2e21a3068cd62a6ce43ef8b592844c1b13'>emulator-5554.log</a>: uploaded 22:39:53 INFO - (blobuploader) - INFO - Blobserver returned 202. File uploaded! 22:39:53 INFO - (blobuploader) - INFO - Done attempting. 22:39:53 INFO - (blobuploader) - INFO - Iteration through files over. 22:39:53 INFO - Return code: 0 22:39:53 INFO - Copying logs to upload dir... 22:39:53 INFO - mkdir: /builds/slave/test/build/upload/logs program finished with exit code 1
Near as I could tell, this started on m-c with the merge from m-i in https://tbpl.mozilla.org/?rev=afa67a2f7905, despite not having happened on m-i. My theory, since I'd previously clobbered m-i, was that something in that merge needed a clobber, so I clobbered everything and it looked to be slowing down, but then the one in https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=e453f32c9c75 was pretty firmly post-clobber.
I'll investigate this today. Current guess is its related to this earlier in the log: [Child 730] WARNING: Called close() before start()!: 'mStarted', file ../../../gecko/dom/workers/MessagePort.cpp, line 214 Which may be a case we did not consider in the code.
Assignee: nobody → bkelly
Status: NEW → ASSIGNED
The failing test does this: var port = new SharedWorker('data:application/javascript,1').port; port.close(); SpecialPowers.forceGC(); ok(true, "No crash \\o/"); So definitely seems possible we are hitting some race related to "closed before we started".
(Tweaking summary to make this TBPL starrable)
Summary: Intermittent MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ../../../gecko/ipc/glue/BackgroundImpl.cpp:380 → Intermittent B2G debug mochitest-12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380" ("Return code: 1")
(In reply to Ed Morley [:edmorley UTC+0] from comment #7) > (Tweaking summary to make this TBPL starrable) Bah I've just remembered we blacklisted "Return code: 1" (it had too many results).
Summary: Intermittent B2G debug mochitest-12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380" ("Return code: 1") → Intermittent B2G debug mochitest-12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380"
Spent most of today trying to reproduce locally, but unfortunately haven't had any luck. I got an emulator build running, but it won't reproduce on my fast dev machine. I'm going to fall back to try-debugging.
Unsure if it's related, but this just failed on OSX with the same assertion failure: https://tbpl.mozilla.org/php/getParsedLog.php?id=42808855&tree=Mozilla-Inbound I filed it as bug 1032605 in case it's a separate issue.
I've found at least one problem where this assert is incorrect if we trigger a shutdown before the actor is opened. I'm testing a bunch of try pushes to see if this is the main issue now.
Debugging this through try is going slow, but this patch might help. It attempts to handle asynchronous ActorDestroy() calls which can happen under certain error conditions. https://tbpl.mozilla.org/?tree=Try&rev=aaf02d4d0ec6
Finally got some good debug out that shows that this error is occurring because we take this path: http://dxr.mozilla.org/mozilla-central/source/ipc/glue/MessageChannel.cpp#1664 Which is the async path comment 29 tries to fix. That patch is looking good so far, but I want to do a number of retriggers to see if I can get any of these failures to re-occur.
Unfortunately that patch seems to have trouble on the b2g debug emulator for some reason. Again, this does not reproduce on my local debug emulator build. Very frustrating. Debugging on try is so slow I'm starting to lean towards a backout for now.
Just an update. I still feel the solution here is making the code support async ActorDestroy(). I'm working through the issues with that in the debugger now. If I don't have a patch by the end of today, then I'll back out bug 1013571 until I can resolve this.
I have a solution that solves things in the debugger. I will have a new try build up shortly.
Updated patch and try build: https://tbpl.mozilla.org/?tree=Try&rev=a0e05edae990 Asking for review immediately since these fixes will be needed no matter what. We must handle async MessageChannel::Close() in the error case and we must fix DoWorkRunnable::Cancel().
Attachment #8448877 - Attachment is obsolete: true
Attachment #8450250 - Flags: review?(bent.mozilla)
Comment on attachment 8450250 [details] [diff] [review] Handle async ActorDestroy() callback when closing PBackground. (v1) Review of attachment 8450250 [details] [diff] [review]: ----------------------------------------------------------------- ::: ipc/glue/BackgroundImpl.cpp @@ +410,5 @@ > static BackgroundChildImpl::ThreadLocal* > GetThreadLocalForCurrentThread(); > > + void > + DoRelease() Nit: Let's call this "ProxyReleaseToMainThread" @@ +424,5 @@ > + if (mActorDestroyed) { > + DoRelease(); > + return; > + } > + mReleaseOnActorDestroy = true; Please assert that this is false first. @@ +440,5 @@ > + // handle both. ReleaseOnActorDestroy() will free the actor > + // immediately in the sync case or defer until ActorDestroy in the > + // async case. > + ChildImpl* actor; > + threadLocalInfo->mActor.forget(&actor); Rather than increasing the refcount for an unbounded time lets add a self-ref nsRefPtr that gets set in this case. @@ +452,5 @@ > DispatchFailureCallback(nsIEventTarget* aEventTarget); > > // This class is reference counted. > ~ChildImpl() > { Can't we keep this? @@ +2021,1 @@ > mActorDestroyed = true; Hm, why'd you change the order here? ::: ipc/glue/MessagePump.cpp @@ +60,5 @@ > NS_DECL_NSICANCELABLERUNNABLE > > + // The pump reuses the same DoWorkRunnable object, so allow > + // the cancel to be cleared before rescheduling. > + void ClearCancel() This is racy... Let's remove all the canceled flags since this is a runnable that gets reused
Attachment #8450250 - Flags: review?(bent.mozilla) → review-
(In reply to ben turner [:bent] (use the needinfo? flag!) from comment #55) > Can't we keep this? Er, there was an assertion there before, now it's gone.
Updated patch with review feedback. I might have gone overboard with the comments. https://tbpl.mozilla.org/?tree=Try&rev=e7a200c07c2d
Attachment #8450250 - Attachment is obsolete: true
Attachment #8450315 - Flags: review?(bent.mozilla)
Comment on attachment 8450315 [details] [diff] [review] Handle async ActorDestroy() callback when closing PBackground. (v2) Review of attachment 8450315 [details] [diff] [review]: ----------------------------------------------------------------- ::: ipc/glue/BackgroundImpl.cpp @@ +413,5 @@ > + ProxyReleaseToMainThread() > + { > + // ChildImpl uses non-threadsafe ref counts, so we must release on > + // the same thread where it was created; the main thread. > + mSelfRefWhileWaitingForActorDestroy.forget(); Nit: I'd prefer you forget() to a stack ChildImpl* that you then pass to NS_NewNonOwningRunnableMethod. @@ +427,5 @@ > + MOZ_ASSERT(!mSelfRefWhileWaitingForActorDestroy); > + mSelfRefWhileWaitingForActorDestroy = this; > + if (mActorDestroyed) { > + ProxyReleaseToMainThread(); > + return; Nit: No need for this return anymore. @@ +445,5 @@ > + // immediately in the sync case or defer until ActorDestroy in the > + // async case. > + ChildImpl* actor; > + threadLocalInfo->mActor.forget(&actor); > + actor->ReleaseOnActorDestroy(); This will leak, you're going to have two refs now...
Attachment #8450315 - Flags: review?(bent.mozilla) → review-
Attachment #8450315 - Attachment is obsolete: true
Attachment #8450399 - Flags: review?(bent.mozilla)
Comment on attachment 8450399 [details] [diff] [review] Handle async ActorDestroy() callback when closing PBackground. (v3) Review of attachment 8450399 [details] [diff] [review]: ----------------------------------------------------------------- r=me with these fixes, thanks a ton! ::: ipc/glue/BackgroundImpl.cpp @@ +409,5 @@ > static BackgroundChildImpl::ThreadLocal* > GetThreadLocalForCurrentThread(); > > + void > + ProxyReleaseToMainThread() Nit: This is only called once now so let's remove the method and inline it into ActorDestroy. @@ +414,5 @@ > + { > + // ChildImpl uses non-threadsafe ref counts, so we must release on > + // the same thread where it was created; the main thread. > + ChildImpl* actor; > + mSelfRefWhileWaitingForActorDestroy.forget(&actor); Nit: MOZ_ASSERT(actor) here, and then add a newline after. @@ +433,5 @@ > + // released automatically when ActorDestroy() is called; either > + // immediately or later. > + ChildImpl* actor; > + threadLocalInfo->mActor.forget(&actor); > + MOZ_ASSERT(!actor->mSelfRefWhileWaitingForActorDestroy); Nit: Please add a newline above here. @@ +435,5 @@ > + ChildImpl* actor; > + threadLocalInfo->mActor.forget(&actor); > + MOZ_ASSERT(!actor->mSelfRefWhileWaitingForActorDestroy); > + actor->mSelfRefWhileWaitingForActorDestroy = dont_AddRef(actor); > + actor->Close(); Nit: and here @@ +2011,5 @@ > ChildImpl::ActorDestroy(ActorDestroyReason aWhy) > { > AssertIsOnBoundThread(); > > mActorDestroyed = true; Nit: Can you add a MOZ_ASSERT(!mActorDestroyed) before this please? @@ +2013,5 @@ > AssertIsOnBoundThread(); > > mActorDestroyed = true; > BackgroundChildImpl::ActorDestroy(aWhy); > + if (mSelfRefWhileWaitingForActorDestroy) { Nit: Newline above here.
Attachment #8450399 - Flags: review?(bent.mozilla) → review+
Updated with review feedback. One last try build for sanity: https://tbpl.mozilla.org/?tree=Try&rev=fc84d80ce4e4 I also verified the patch again in the debugger.
Attachment #8450399 - Attachment is obsolete: true
Attachment #8450417 - Flags: review+
There is still a race... try is unhappy.
Updated to delay the start of release until ActorDestroy call stack has completed. I'm short on time at the moment, so this is only lightly tested locally. Here is the try build: https://tbpl.mozilla.org/?tree=Try&rev=0f91738896b3
Attachment #8450417 - Attachment is obsolete: true
Attachment #8450556 - Flags: review?(bent.mozilla)
Comment on attachment 8450556 [details] [diff] [review] Handle async ActorDestroy() callback when closing PBackground. (v5) Review of attachment 8450556 [details] [diff] [review]: ----------------------------------------------------------------- I think this is ok, but there are some cases we won't handle properly still. Whether they're possible or not... I don't know. See below for places to add assertions. ::: ipc/glue/BackgroundImpl.cpp @@ +353,5 @@ > nsIThread* mBoundThread; > #endif > > + bool mActorDestroyed; > + nsRefPtr<ChildImpl> mSelfRefWhileWaitingForActorDestroy; Nit: put the bool last. @@ +414,5 @@ > > static void > ThreadLocalDestructor(void* aThreadLocal) > { > auto threadLocalInfo = static_cast<ThreadLocalInfo*>(aThreadLocal); We may need some additional state here... If the thread is really going away (as opposed to if we're calling CloseForCurrentThread()) then this code is going to not work at all... Maybe we shouldn't have to worry about it yet since we should always call CloseForCurrentThread() before the thread dies. @@ +428,3 @@ > > + MOZ_ASSERT(!actor->mSelfRefWhileWaitingForActorDestroy); > + actor->mSelfRefWhileWaitingForActorDestroy = dont_AddRef(actor); Hmm... So what happens here if mActorDestroyed is already true? I think this case is also possible... Maybe MOZ_ASSERT(!mActorDestroyed) for now to see if we have to worry about it? @@ +793,5 @@ > + } > + > + NS_DECL_ISUPPORTS > + NS_DECL_NSIRUNNABLE > + NS_DECL_NSICANCELABLERUNNABLE Nit: These two runnable DECLS should be moved after the destructor in the private section @@ +798,5 @@ > + > +private: > + ~DelayedReleaseRunnable() > + { > + } Nit: { } @@ +1948,5 @@ > + > + AutoRestore<bool> restore(mCallingRunWhileCanceled); > + mCallingRunWhileCanceled = true; > + > + Run(); Nit: MOZ_ALWAYS_TRUE(NS_SUCCEEDED(Run())); @@ +2074,3 @@ > BackgroundChildImpl::ActorDestroy(aWhy); > + > + if (mSelfRefWhileWaitingForActorDestroy) { This should always be set now, right? Unless we're somehow being called not from ThreadLocalDestructor... Maybe you should just assert this currently. @@ +2077,5 @@ > + // We need to release, but there is additional teardown work for the actor > + // after leaving ActorDestroy(). Therefore, dispatch to the current thread > + // to guarantee this work has completed before starting the release. > + nsCOMPtr<nsIRunnable> delayedRelease = > + new ChildImpl::DelayedReleaseRunnable(mSelfRefWhileWaitingForActorDestroy.forget()); Nit: No need for 'ChildImpl::'
Attachment #8450556 - Flags: review?(bent.mozilla) → review+
I guess this doesn't handle the case where the parent side closes the actor. In that case we would get ActorDestroy() prior to ThreadLocalDestructor, right? As I understand it, though, that can't happen since it would mean the parent process is closing before the child process.
Updated for review feedback. https://tbpl.mozilla.org/?tree=Try&rev=da0512893f3e I will wait for try build and some extra pushes to go green before landing. Hope to do so later tonight, though.
Attachment #8450556 - Attachment is obsolete: true
Attachment #8450633 - Flags: review+
Been seeing these in mochitest-9 today as well. https://tbpl.mozilla.org/php/getParsedLog.php?id=43088225&tree=Mozilla-Inbound
Summary: Intermittent B2G debug mochitest-12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380" → Intermittent B2G debug mochitest-9,12 "MOZ_Assert: Assertion failure: mActorDestroyed (ChildImpl::ActorDestroy not called in time), at ipc/glue/BackgroundImpl.cpp:380"
We still have a problem. We now have a race between when we dispatch DelayedReleaseRunnable to the current thread and when mWorkerPrivate gets set to null. Unfortunately the worker thread requires an mWorkerPrivate to dispatch a runnable to itself. I tried spinning on the NS_ProcessNextEvent() in ThreadLocalDestructor(), but this hit more assertions due to the worker private being torn down. Its painful, but it seems we need to bounce three times here. Worker->Main, Main->Worker, Worker->Main. Or create a worker state where we can dispatch to ourselves.
I pushed a backout of bug 1013571 to mozilla-inbound. See bug 1013571 comment 58. I don't know if we want to keep this bug open because of all the review info or move the relanding discussion back over to bug 1013571.
Here's a different approach to dealing with the async Close() which should avoid all of these races. Here we spin the event loop and essentially block in the ThreadLocalDestructor until we see mActorDestroyed go true. This simplifies things and avoids the need to add all the extra bounces, etc. Let's see how try does: https://tbpl.mozilla.org/?tree=Try&rev=dbcd0cef2cce
Attachment #8450633 - Attachment is obsolete: true
Since the original patch was backed out, I think this is fixed for now. I'm moving patch review stuff back to bug 1013571 now that its reopened.
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: