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)
(deleted), 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: