Closed Bug 899635 Opened 11 years ago Closed 10 years ago

Intermittent Ubuntu64 debug "Marionette exited with return code 256: harness failures" errors since the landing of bug 853301

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: RyanVM, Assigned: Waldo)

References

Details

(Keywords: intermittent-failure)

No clue why, but a multitude of retriggers have narrowed it down to changeset a297a9937018, which was the enabling of the Internationalization API for desktop builds. https://tbpl.mozilla.org/php/getParsedLog.php?id=25913869&tree=Mozilla-Inbound Ubuntu VM 12.04 x64 mozilla-inbound debug test marionette on 2013-07-30 09:05:01 PDT for push a297a9937018 slave: tst-linux64-ec2-004 09:06:57 INFO - ##### 09:06:57 INFO - ##### Running run-marionette step. 09:06:57 INFO - ##### 09:06:57 INFO - Running pre-action listener: _resource_record_pre_action 09:06:57 INFO - Running main action method: run_marionette 09:06:57 INFO - Getting output from command: ['/builds/slave/test/build/venv/bin/python', '-c', 'from distutils.sysconfig import get_python_lib; print(get_python_lib())'] 09:06:57 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python -c "from distutils.sysconfig import get_python_lib; print(get_python_lib())" 09:06:57 INFO - Reading from file tmpfile_stdout 09:06:57 INFO - Output received: 09:06:57 INFO - /builds/slave/test/build/venv/lib/python2.7/site-packages 09:06:57 INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stderr',), kwargs: {}, attempt #1 09:06:57 INFO - retry: Calling <built-in function remove> with args: ('tmpfile_stdout',), kwargs: {}, attempt #1 09:06:57 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '-u', '/builds/slave/test/build/tests/marionette/marionette/runtests.py', '--binary', '/builds/slave/test/build/application/firefox/firefox', '--address', 'localhost:2828', '--type', 'browser', '/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit-tests.ini'] 09:06:57 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python -u /builds/slave/test/build/tests/marionette/marionette/runtests.py --binary /builds/slave/test/build/application/firefox/firefox --address localhost:2828 --type browser /builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit-tests.ini 09:06:57 INFO - /builds/slave/test/build/venv/local/lib/python2.7/site-packages/mozrunner/utils.py:20: UserWarning: Module marionette was already imported from /builds/slave/test/build/tests/marionette/marionette/marionette.py, but /builds/slave/test/build/venv/lib/python2.7/site-packages is being added to sys.path 09:06:57 INFO - import pkg_resources 09:06:57 INFO - starting httpd 09:06:58 INFO - running webserver on http://10.134.57.70:52440/ 09:06:58 INFO - Xlib: extension "RANDR" missing on display ":0". 09:07:00 INFO - 1375200420542 Marionette INFO MarionetteComponent loaded 09:07:00 INFO - ++DOCSHELL 0x1f8af90 == 1 [id = 1] 09:07:00 INFO - ++DOMWINDOW == 1 (0x1f654b8) [serial = 1] [outer = (nil)] 09:07:00 INFO - ++DOMWINDOW == 2 (0x1fa5718) [serial = 2] [outer = 0x1f654b8] 09:07:01 INFO - pldhash: for the table at address 0x20fbd68, the given entrySize of 168 definitely favors chaining over double hashing. 09:07:01 INFO - WARNING: No disk space watcher component available!: file ../../../dom/indexedDB/IndexedDatabaseManager.cpp, line 174 09:07:02 INFO - 1375200422691 Marionette INFO marionette enabled via command-line 09:07:02 INFO - 1375200422706 Marionette INFO marionette-server.js loaded 09:07:02 INFO - WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file ../../../../js/xpconnect/loader/mozJSComponentLoader.cpp, line 953 09:07:02 INFO - 1375200422791 Marionette INFO Listening on port 2828 09:07:02 INFO - 1375200422794 Marionette INFO Marionette server ready 09:07:02 INFO - ++DOCSHELL 0x264a310 == 2 [id = 2] 09:07:02 INFO - ++DOMWINDOW == 3 (0x2650728) [serial = 3] [outer = (nil)] 09:07:02 INFO - ++DOMWINDOW == 4 (0x2654078) [serial = 4] [outer = 0x2650728] 09:07:02 INFO - ++DOMWINDOW == 5 (0x26fcc78) [serial = 5] [outer = 0x1f654b8] 09:07:03 INFO - 1375200423298 Marionette DEBUG accepted connection on 127.0.0.1:37691 09:07:03 INFO - 1375200423929 Marionette INFO sendToClient: {"from":"0","ok":true}, {2937b4a0-37c7-4f1e-87f9-c864f34c481f}, {2937b4a0-37c7-4f1e-87f9-c864f34c481f} 09:07:03 INFO - 1375200423998 Marionette TRACE Connection closed. 09:07:04 INFO - ++DOCSHELL 0x2caa850 == 3 [id = 3] 09:07:04 INFO - ++DOMWINDOW == 6 (0x2cabdb8) [serial = 6] [outer = (nil)] 09:07:04 INFO - ++DOCSHELL 0x2cae7a0 == 4 [id = 4] 09:07:04 INFO - ++DOMWINDOW == 7 (0x2caf328) [serial = 7] [outer = (nil)] 09:07:07 INFO - WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file ../../../../content/base/src/nsFrameLoader.cpp, line 401 09:07:07 INFO - ++DOCSHELL 0x3473c90 == 5 [id = 5] 09:07:07 INFO - ++DOMWINDOW == 8 (0x3475278) [serial = 8] [outer = (nil)] 09:07:07 INFO - WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file ../../../../content/base/src/nsFrameLoader.cpp, line 401 09:07:07 INFO - ++DOMWINDOW == 9 (0x35ee0b8) [serial = 9] [outer = 0x3475278] 09:07:07 INFO - WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file ../../../docshell/base/nsDocShell.cpp, line 8392 09:07:07 INFO - WARNING: OpenGL-accelerated layers are not supported on this system: file ../../../widget/xpwidgets/nsBaseWidget.cpp, line 893 09:07:07 INFO - WARNING: Subdocument container has no frame: file ../../../layout/base/nsDocumentViewer.cpp, line 2374 09:07:07 INFO - ++DOMWINDOW == 10 (0x37023f8) [serial = 10] [outer = 0x2cabdb8] 09:07:07 INFO - WARNING: Subdocument container has no frame: file ../../../layout/base/nsDocumentViewer.cpp, line 2374 09:07:07 INFO - ++DOMWINDOW == 11 (0x3714188) [serial = 11] [outer = 0x2caf328] 09:07:07 INFO - ++DOMWINDOW == 12 (0x372ff58) [serial = 12] [outer = 0x3475278] 09:07:08 INFO - 1375200428588 Marionette DEBUG accepted connection on 127.0.0.1:37692 09:07:08 INFO - 1375200428884 Marionette TRACE Got: {"to": "root", "type": "getMarionetteID"} 09:07:08 INFO - 1375200428896 Marionette TRACE Got: {"to": "0", "type": "newSession"} 09:07:08 INFO - ++DOCSHELL 0x3a7aba0 == 6 [id = 6] 09:07:08 INFO - ++DOMWINDOW == 13 (0x3a7c0d8) [serial = 13] [outer = (nil)] 09:07:09 INFO - ++DOMWINDOW == 14 (0x3aca878) [serial = 14] [outer = 0x3a7c0d8] 09:07:09 INFO - ++DOMWINDOW == 15 (0x3b83bc8) [serial = 15] [outer = 0x3a7c0d8] 09:07:09 INFO - 1375200429501 Marionette INFO loaded marionette-listener.js 09:07:09 INFO - 1375200429577 Marionette INFO loaded marionette-listener.js 09:07:09 INFO - 1375200429623 Marionette INFO loaded marionette-listener.js 09:07:09 INFO - 1375200429630 Marionette INFO sendToClient: {"from":"0","value":"13"}, {5ae3e6fb-59f3-4c95-9397-100f5bec8aea}, {5ae3e6fb-59f3-4c95-9397-100f5bec8aea} 09:07:09 INFO - 1375200429690 Marionette TRACE Got: {"to": "0", "session": "13", "type": "getSessionCapabilities"} 09:07:09 INFO - 1375200429696 Marionette INFO sendToClient: {"from":"0","value":{"appBuildId":"20130729145427","XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","cssSelectorsEnabled":true,"browserName":"Firefox","handlesAlerts":false,"javascriptEnabled":true,"nativeEvents":false,"platform":"Linux","device":"desktop","rotatable":false,"takesScreenshot":false,"version":"25.0a1"}}, {5fbdfe90-7250-4e0c-a025-1b91f6608167}, {5fbdfe90-7250-4e0c-a025-1b91f6608167} 09:07:09 INFO - 1375200429706 Marionette TRACE Got: {"to": "0", "session": "13", "type": "deleteSession"} 09:07:09 INFO - Traceback (most recent call last): 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 791, in <module> 09:07:09 INFO - cli() 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 786, in cli 09:07:09 INFO - runner = startTestRunner(runner_class, options, tests) 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 778, in startTestRunner 09:07:09 INFO - runner.run_tests(tests) 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 423, in run_tests 09:07:09 INFO - self.run_test(test) 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 499, in run_test 09:07:09 INFO - device=self.device, 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 293, in device 09:07:09 INFO - self._device = self.capabilities.get('device') 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 285, in capabilities 09:07:09 INFO - self.marionette.delete_session() 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 465, in delete_session 09:07:09 INFO - response = self._send_message('deleteSession', 'ok') 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 352, in _send_message 09:07:09 INFO - self._handle_error(response) 09:07:09 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 414, in _handle_error 09:07:09 INFO - raise MarionetteException(message=response, status=500) 09:07:09 INFO - errors.MarionetteException: {u'message': {}, u'error': u"error occurred while processing 'deleteSession"} 09:07:10 ERROR - Return code: 256 09:07:10 INFO - gecko.log not found 09:07:10 INFO - TinderboxPrint: marionette: <em class="testfail">T-FAIL</em> 09:07:10 ERROR - Marionette exited with return code 256: harness failures 09:07:10 ERROR - # TBPL FAILURE # 09:07:10 INFO - Running post-action listener: _resource_record_post_action 09:07:10 INFO - Running post-run listener: _resource_record_post_run 09:07:11 INFO - Total resource usage - Wall time: 27s; CPU: 99%; Read bytes: 4030464; Write bytes: 40722432; Read time: 2988; Write time: 109500 09:07:11 INFO - install - Wall time: 15s; CPU: 100%; Read bytes: 868352; Write bytes: 23314432; Read time: 272; Write time: 72804 09:07:11 INFO - run-marionette - Wall time: 13s; CPU: 100%; Read bytes: 2453504; Write bytes: 17408000; Read time: 2572; Write time: 36696
I am currently working through https://developer.mozilla.org/en-US/docs/Marionette at P1 priority to hopefully figure out this craziness, fwiw. If there's anything I need to know that isn't documented on that page or via links from it, people should chime in and explain. :-)
CCing a few ATeamers who are familiar with Marionette.
Depends on: 892958
There's a small bug in Marionette which is causing us to lose some error information here; at http://mxr.mozilla.org/mozilla-central/source/testing/marionette/marionette-server.js#171, 'e' should be 'e.message'. I'll push this fix asap. Hopefully that will help us see what the problem is.
Depends on: 900080
So with the patch from bug 900080, this gives us more info: 16:36:04 INFO - errors.MarionetteException: {u'message': u"'Illegal value' when calling method: [nsISessionStore::setNumberOfTabsClosedLast]", u'error': u"error occurred while processing 'deleteSession"}
(In reply to Jonathan Griffin (:jgriffin) from comment #11) > So with the patch from bug 900080, this gives us more info: > > 16:36:04 INFO - errors.MarionetteException: {u'message': u"'Illegal > value' when calling method: [nsISessionStore::setNumberOfTabsClosedLast]", > u'error': u"error occurred while processing 'deleteSession"} Probably coming from: http://mxr.mozilla.org/mozilla-central/source/testing/marionette/marionette-server.js#1969
I was curious how successful test runs differ from failing ones, and noticed one strange difference in the logs: The successful runs have a few warnings that the failing ones don't have, just before the point where the failing runs actually fail. I've marked the lines of a successful log that have no equivalent in a failing log with ">": 16:40:51 INFO - WARNING: Subdocument container has no frame: file ../../../layout/base/nsDocumentViewer.cpp, line 2374 16:40:51 INFO - ++DOMWINDOW == 11 (0x44dbe28) [serial = 11] [outer = 0x3a73298] 16:40:51 INFO - ++DOMWINDOW == 12 (0x44f5e18) [serial = 12] [outer = 0x423ca58] > 16:40:52 INFO - WARNING: NS_ENSURE_TRUE(!aStringURI.IsEmpty()) failed: file ../../../docshell/base/nsDefaultURIFixup.cpp, line 119 > 16:40:53 INFO - WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 266 16:40:53 INFO - 1375314053907 Marionette DEBUG accepted connection on 127.0.0.1:39777 16:40:53 INFO - 1375314053922 Marionette TRACE Got: {"to": "root", "type": "getMarionetteID"} 16:40:53 INFO - 1375314053931 Marionette TRACE Got: {"to": "0", "type": "newSession"} 16:40:53 INFO - ++DOCSHELL 0x4b58b80 == 6 [id = 6] 16:40:53 INFO - ++DOMWINDOW == 13 (0x4b5a088) [serial = 13] [outer = (nil)] 16:40:54 INFO - ++DOMWINDOW == 14 (0x4ba8238) [serial = 14] [outer = 0x4b5a088] > 16:40:54 INFO - WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 266 > 16:40:54 INFO - WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 266 16:40:54 INFO - ++DOMWINDOW == 15 (0x4c34678) [serial = 15] [outer = 0x4b5a088] > 16:40:54 INFO - WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 266 16:40:54 INFO - 1375314054945 Marionette INFO loaded marionette-listener.js 16:40:55 INFO - 1375314055005 Marionette INFO loaded marionette-listener.js 16:40:55 INFO - 1375314055050 Marionette INFO loaded marionette-listener.js 16:40:55 INFO - 1375314055056 Marionette INFO sendToClient: {"from":"0","value":"13"}, {0d750893-bc91-4671-8fa0-8d6aa8dba934}, {0d750893-bc91-4671-8fa0-8d6aa8dba934} 16:40:55 INFO - 1375314055171 Marionette TRACE Got: {"to": "0", "session": "13", "type": "getSessionCapabilities"} 16:40:55 INFO - 1375314055178 Marionette INFO sendToClient: {"from":"0","value":{"appBuildId":"20130731150450","XULappId":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","cssSelectorsEnabled":true,"browserName":"Firefox","handlesAlerts":false,"javascriptEnabled":true,"nativeEvents":false,"platform":"Linux","device":"desktop","rotatable":false,"takesScreenshot":false,"version":"25.0a1"}}, {748e1113-b355-4c30-8a84-e71d14e31dd8}, {748e1113-b355-4c30-8a84-e71d14e31dd8} 16:40:55 INFO - 1375314055186 Marionette TRACE Got: {"to": "0", "session": "13", "type": "deleteSession"} > 16:40:55 INFO - WARNING: NS_ENSURE_TRUE(mMutable) failed: file ../../../../netwerk/base/src/nsSimpleURI.cpp, line 266 This is the point where the failure occurs in the failing runs. I have no idea what this means, if anything, but maybe somebody else has an idea... The section above is from https://tbpl.mozilla.org/php/getParsedLog.php?id=25994954&tree=Mozilla-Inbound&full=1 a nearby failing log is https://tbpl.mozilla.org/php/getParsedLog.php?id=25994525&full=1&branch=mozilla-inbound
On the browser side, this seems like it might be hitting http://hg.mozilla.org/mozilla-central/annotate/05d3797276d3/browser/components/sessionstore/src/SessionStore.jsm#l1577 which doesn't track back meaningfully. My guess is those warnings are a symptom of something extra happening, that doesn't happen in the builds that fail. But I don't have a huge amount more understanding of this (other than wrt the location of the failing thing) than I did before getting the elaborated error message.
These errors are all occurring at the very beginning of the test run. When Marionette creates a new session, it opens a tab...is it possible that doing this too early after browser startup now silently fails, causing a later attempt to close the tab to error out?
Comment 32's hit for this is thoroughly bizarre. That hit is with ICU and the Intl API stuff built, but without it being enabled/exposed to JS. That is, that build should be exactly identical in functionality to builds without any ICU stuff in them at all. We shouldn't init ICU, we shouldn't destroy it, we should be ignoring it completely at runtime. Why this intermittent failure would occur in that situation, then, eludes me completely. Maybe it's something about binary/library size, tickled only incidentally? I got nothin'.
Closing bugs where TBPLbot has previously commented, but have now not been modified for >3 months & do not contain the whiteboard strings for disabled/annotated tests or use the keyword leave-open. Filter on: mass-intermittent-bug-closure-2014-07
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.