Closed Bug 976790 Opened 6 years ago Closed 6 years ago

Intermittent PROCESS-CRASH | base.py | application crashed [Unknown top frame] | Assertion failure: currentPRThread != sBackgroundPRThread

Categories

(Core :: IPC, defect)

x86_64
Windows 8.1
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla30
Tracking Status
firefox28 --- unaffected
firefox29 --- unaffected
firefox30 --- fixed
firefox-esr24 --- unaffected

People

(Reporter: KWierso, Assigned: bent.mozilla)

Details

(Keywords: crash, intermittent-failure)

Attachments

(1 file, 1 obsolete file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=35235682&tree=Fx-Team
slave: talos-mtnlion-r5-068



13:12:33     INFO -  test_stack_trace (test_switch_frame_chrome.TestSwitchFrameChrome) ... ok
13:12:34     INFO -  test_switch_simple (test_switch_frame_chrome.TestSwitchFrameChrome) ... ok
13:12:34     INFO -  ----------------------------------------------------------------------
13:12:34     INFO -  Ran 2 tests in 1.978s
13:12:34     INFO -  OK
13:12:34     INFO -  TEST-START test_switch_remote_frame.py
13:12:38     INFO -  test_remote_frame (test_switch_remote_frame.TestSwitchRemoteFrame) ... ok
13:12:51     INFO -  test_remote_frame_revisit (test_switch_remote_frame.TestSwitchRemoteFrame) ... ERROR
13:12:51     INFO -  ERROR
13:12:51     INFO -  PROCESS-CRASH | base.py | application crashed [Unknown top frame]
13:12:51     INFO -  Crash dump filename: /var/folders/rx/_s2192dn6j30_5kykk2bghl400000w/T/tmp6RcZtg.mozrunner/minidumps/3E768841-8962-43B8-9C7B-040F41BEACDB.dmp
13:12:51     INFO -  No symbols path given, can't process dump.
13:12:51     INFO -  MINIDUMP_STACKWALK not set, can't process dump.
13:12:51     INFO -  mozcrash INFO | Saved minidump as /builds/slave/talos-slave/test/build/blobber_upload_dir/3E768841-8962-43B8-9C7B-040F41BEACDB.dmp
13:12:51     INFO -  mozcrash INFO | Saved app info as /builds/slave/talos-slave/test/build/blobber_upload_dir/3E768841-8962-43B8-9C7B-040F41BEACDB.extra
13:12:51     INFO -  Traceback (most recent call last):
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runtests.py", line 33, in <module>
13:12:51     INFO -      cli()
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runtests.py", line 28, in cli
13:12:51     INFO -      runner = startTestRunner(runner_class, options, tests)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runtests.py", line 19, in startTestRunner
13:12:51     INFO -      runner.run_tests(tests)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runner/base.py", line 778, in run_tests
13:12:51     INFO -      self.run_test_sets()
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runner/base.py", line 975, in run_test_sets
13:12:51     INFO -      self.run_test_set(in_process_tests)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runner/base.py", line 966, in run_test_set
13:12:51     INFO -      self.run_test(test['filepath'], test['expected'], test['oop'])
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runner/base.py", line 945, in run_test
13:12:51     INFO -      results = runner.run(suite)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/runner/base.py", line 264, in run
13:12:51     INFO -      test(result)
13:12:51     INFO -    File "/tools/python27/lib/python2.7/unittest/suite.py", line 70, in __call__
13:12:51     INFO -      return self.run(*args, **kwds)
13:12:51     INFO -    File "/tools/python27/lib/python2.7/unittest/suite.py", line 108, in run
13:12:51     INFO -      test(result)
13:12:51     INFO -    File "/tools/python27/lib/python2.7/unittest/case.py", line 391, in __call__
13:12:51     INFO -      return self.run(*args, **kwds)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 200, in run
13:12:51     INFO -      self.cleanTest()
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 279, in cleanTest
13:12:51     INFO -      self._deleteSession()
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 291, in _deleteSession
13:12:51     INFO -      self.marionette.delete_session()
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 741, in delete_session
13:12:51     INFO -      response = self._send_message('deleteSession', 'ok')
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 598, in _send_message
13:12:51     INFO -      response = self.client.send(message)
13:12:51     INFO -    File "/builds/slave/talos-slave/test/build/tests/marionette/marionette/client.py", line 97, in send
13:12:51     INFO -      raise IOError("%s: Connection to Marionette server is lost. Check gecko.log (desktop firefox) or logcat (b2g) for errors." % str(e))
13:12:51     INFO -  IOError: [Errno 32] Broken pipe: Connection to Marionette server is lost. Check gecko.log (desktop firefox) or logcat (b2g) for errors.
13:12:51     INFO -  Exception IOError: IOError('[Errno 32] Broken pipe: Connection to Marionette server is lost. Check gecko.log (desktop firefox) or logcat (b2g) for errors.',) in <bound method Marionette.__del__ of <marionette.Marionette object at 0x1016c0950>> ignored
13:12:51     INFO -  Could not kill process, could not find pid: 1177, assuming it's already dead
13:12:51    ERROR - Return code: 1



LATER



13:12:55     INFO -  1393362758298	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"marionette_test.py","script":"log('TEST-START: /builds/slave/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_switch_remote_frame.py:test_remote_frame_revisit')","line":335}}, id: {46d4bd71-6897-e44f-9b9b-f9fffc90dcd0}
13:12:55     INFO -  MARIONETTE LOG: INFO: TEST-START: /builds/slave/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_switch_remote_frame.py:test_remote_frame_revisit
13:12:55     INFO -  1393362758301	Marionette	INFO	sendToClient: {"from":"0","value":null}, {46d4bd71-6897-e44f-9b9b-f9fffc90dcd0}, {46d4bd71-6897-e44f-9b9b-f9fffc90dcd0}
13:12:55     INFO -  1393362758303	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"\n            try {\n              return SpecialPowers.getBoolPref('dom.ipc.browser_frames.oop_by_default');\n            }\n            catch(e) {}\n            ","line":16}}, id: {ec55dca5-67f8-864c-a84e-e941821b15fd}
13:12:55     INFO -  1393362758306	Marionette	INFO	sendToClient: {"from":"0","value":true}, {ec55dca5-67f8-864c-a84e-e941821b15fd}, {ec55dca5-67f8-864c-a84e-e941821b15fd}
13:12:55     INFO -  1393362758311	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"\n            try {\n              return SpecialPowers.getBoolPref('dom.mozBrowserFramesEnabled');\n            }\n            catch(e) {}\n            ","line":22}}, id: {323bb4a9-7cdc-6843-ad07-5015818d33ea}
13:12:55     INFO -  1393362758314	Marionette	INFO	sendToClient: {"from":"0","value":true}, {323bb4a9-7cdc-6843-ad07-5015818d33ea}, {323bb4a9-7cdc-6843-ad07-5015818d33ea}
13:12:55     INFO -  1393362758317	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"\n            SpecialPowers.setBoolPref('dom.ipc.browser_frames.oop_by_default', true);\n            ","line":25}}, id: {18c368fd-dfe1-bf4a-94d3-c6422b55921f}
13:12:55     INFO -  1393362758319	Marionette	INFO	sendToClient: {"from":"0","value":null}, {18c368fd-dfe1-bf4a-94d3-c6422b55921f}, {18c368fd-dfe1-bf4a-94d3-c6422b55921f}
13:12:55     INFO -  1393362758322	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"\n            SpecialPowers.setBoolPref('dom.mozBrowserFramesEnabled', true);\n            ","line":28}}, id: {8a3d4b3c-6434-7341-86b5-4179f4176cba}
13:12:55     INFO -  1393362758329	Marionette	INFO	sendToClient: {"from":"0","value":null}, {8a3d4b3c-6434-7341-86b5-4179f4176cba}, {8a3d4b3c-6434-7341-86b5-4179f4176cba}
13:12:55     INFO -  [Parent 1177] WARNING: NS_ENSURE_TRUE(window) failed: file /builds/slave/fx-team-osx64-d-00000000000000/build/dom/base/nsLocation.cpp, line 44
13:12:55     INFO -  ++DOMWINDOW == 75 (0x13c19e3c0) [pid = 1177] [serial = 831] [outer = 0x129d7bf70]
13:12:55     INFO -  1393362758477	Marionette	INFO	sendToClient: {"from":"0","ok":true}, {36bd1b76-be85-b34c-bd72-66e52c36a532}, {36bd1b76-be85-b34c-bd72-66e52c36a532}
13:12:55     INFO -  1393362758481	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"SpecialPowers.addPermission('browser', true, document)","line":52}}, id: {e74aee38-8dd2-6045-83d8-b4ac1d617a55}
13:12:55     INFO -  1393362758486	Marionette	INFO	sendToClient: {"from":"0","value":null}, {e74aee38-8dd2-6045-83d8-b4ac1d617a55}, {e74aee38-8dd2-6045-83d8-b4ac1d617a55}
13:12:55     INFO -  1393362758489	Marionette	DEBUG	Got request: execute, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"executeScript","parameters":{"specialPowers":false,"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_switch_remote_frame.py","script":"\n            let iframe = document.createElement(\"iframe\");\n            SpecialPowers.wrap(iframe).mozbrowser = true;\n            SpecialPowers.wrap(iframe).remote = true;\n            iframe.id = \"remote_iframe\";\n            iframe.style.height = \"100px\";\n            iframe.style.width = \"100%\";\n            iframe.src = \"http://10.26.56.88:49201/test.html\";\n            document.body.appendChild(iframe);\n            ","line":62}}, id: {831d7e38-4093-7146-bd78-4fcb17d7d8a2}
13:12:55     INFO -  [1181] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/fx-team-osx64-d-00000000000000/build/xpcom/base/nsTraceRefcntImpl.cpp, line 142
13:12:55     INFO -  [1181] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/fx-team-osx64-d-00000000000000/build/xpcom/base/nsTraceRefcntImpl.cpp, line 142
13:12:55     INFO -  1393362758533	Marionette	INFO	sendToClient: {"from":"0","value":null}, {831d7e38-4093-7146-bd78-4fcb17d7d8a2}, {831d7e38-4093-7146-bd78-4fcb17d7d8a2}
13:12:55     INFO -  [Child 1181] WARNING: '!compMgr', file /builds/slave/fx-team-osx64-d-00000000000000/build/xpcom/glue/nsComponentManagerUtils.cpp, line 59
13:12:55     INFO -  [Child 1181] WARNING: NS_ENSURE_TRUE(svc) failed: file /builds/slave/fx-team-osx64-d-00000000000000/build/dom/ipc/ContentChild.cpp, line 706
13:12:55     INFO -  [Child 1181] WARNING: '!compMgr', file /builds/slave/fx-team-osx64-d-00000000000000/build/xpcom/glue/nsComponentManagerUtils.cpp, line 59
13:12:55     INFO -  1393362758536	Marionette	DEBUG	Got request: switchToFrame, data: {"to":"0","sessionId":{"rotatable":false,"browserVersion":"30.0a1","takesScreenshot":true,"appBuildId":"20140225122923","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","secureSsl":false,"platform":"DARWIN","browserName":"Firefox","version":"30.0a1","device":"desktop","nativeEvents":false,"platformVersion":"30.0a1","takesElementScreenshot":true,"platformName":"DARWIN","handlesAlerts":false},"name":"switchToFrame","parameters":{"id":"remote_iframe","focus":true}}, id: {7130ca4b-3f69-b848-b41f-481552c3c5ee}
13:12:55     INFO -  1393362758539	Marionette	INFO	Switched to frame: {"frameValue":"{6bbfe5b8-7a47-1b43-99b1-5662e2b1ccd1}"}
13:12:55     INFO -  [Parent 1177] WARNING: No docshells for remote frames!: file /builds/slave/fx-team-osx64-d-00000000000000/build/content/base/src/nsFrameLoader.cpp, line 616
13:12:55     INFO -  1393362758539	Marionette	INFO	trying remote frame 0
13:12:55     INFO -  [Parent 1177] WARNING: NS_ENSURE_TRUE(mCallback) failed: file /builds/slave/fx-team-osx64-d-00000000000000/build/content/base/src/nsFrameMessageManager.cpp, line 639
13:12:55     INFO -  1393362758540	Marionette	INFO	deleting frame
13:12:55     INFO -  1393362758542	Marionette	INFO	frame-manager load script: [object ChromeMessageSender]
13:12:55     INFO -  Assertion failure: currentPRThread != sBackgroundPRThread, at /builds/slave/fx-team-osx64-d-00000000000000/build/ipc/glue/BackgroundImpl.cpp:1254
13:12:55     INFO -  ###!!! [Child][MessageChannel::SendAndWait] Error: Channel error: cannot send/recv
13:12:55     INFO -  [Child 1181] WARNING: content process _exit()ing: file /builds/slave/fx-team-osx64-d-00000000000000/build/dom/ipc/ContentChild.cpp, line 1244
13:12:55     INFO - Return code: 0
13:12:55     INFO - rmtree: /builds/slave/talos-slave/test/gecko.log
13:12:55     INFO - retry: Calling <built-in function remove> with args: ('/builds/slave/talos-slave/test/gecko.log',), kwargs: {}, attempt #1
13:12:55     INFO - TinderboxPrint: marionette: <em class="testfail">T-FAIL</em>
13:12:55    ERROR - Marionette exited with return code 1: harness failures
13:12:55    ERROR - # TBPL FAILURE #
13:12:55     INFO - Running post-action listener: _resource_record_post_action
13:12:55     INFO - Running post-run listener: _resource_record_post_run
Benoit, RyanVM thinks this might be related to your work in bug 974356.
Group: core-security
Flags: needinfo?(bjacob)
Ah ok, please share your thoughts about how this could have caused that?

There is also an assertion failure that seems unrelated to my changes:
Assertion failure: currentPRThread != sBackgroundPRThread
Flags: needinfo?(bjacob)
:bent, any idea what's going on with these crashes?
Flags: needinfo?(bent.mozilla)
Weird. That's definitely my assertion but I have no idea how it's being tripped.

Assuming that the assertion failure is the cause of this bug then there's no reason it needs to be security-sensitive.
Flags: needinfo?(bent.mozilla)
This happens during Marionette tests that exercise OOP code in desktop Firefox.  By looking at the log, it appears that this assertion occurs when we delete a reference to a frame, which may allow it to be garbage-collected:

http://mxr.mozilla.org/mozilla-central/source/testing/marionette/marionette-frame-manager.js#112
(In reply to Benoit Jacob [:bjacob] from comment #3)
> Ah ok, please share your thoughts about how this could have caused that?
> 
> There is also an assertion failure that seems unrelated to my changes:
> Assertion failure: currentPRThread != sBackgroundPRThread

Just a guess based on the IPC work you've been doing. I have no problem being wrong about that :)
Flags: needinfo?(ryanvm)
Summary: Intermittent PROCESS-CRASH | base.py | application crashed [Unknown top frame] → Intermittent PROCESS-CRASH | base.py | application crashed [Unknown top frame] | Assertion failure: currentPRThread != sBackgroundPRThread
Component: Marionette → IPC
Product: Testing → Core
Ok, I know what this is. It's basically just a bad assertion, nothing serious.
Assignee: nobody → bent.mozilla
Status: NEW → ASSIGNED
Attached patch Patch, v1 (obsolete) — Splinter Review
The basic problem is that I forgot to null out sBackgroundPRThread so we are not protected from pointer replay and this assertion could fail.

However, with the current design I can't just null sBackgroundPRThread out whenever the background thread is shutting down because it's possible that another thread has been created to take its place. Hence the atomic juggling.
Attachment #8382495 - Flags: review?(mrbkap)
Attached patch Patch, v1Splinter Review
Oops, right patch this time.
Attachment #8382495 - Attachment is obsolete: true
Attachment #8382495 - Flags: review?(mrbkap)
Attachment #8382498 - Flags: review?(mrbkap)
Attachment #8382498 - Flags: review?(mrbkap) → review+
https://hg.mozilla.org/mozilla-central/rev/3070f00e7833
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla30
You need to log in before you can comment on or make changes to this bug.