1257922 - Marionette runs on ASAN fail due to fatal NS_ERROR_NOT_IMPLEMENTED JavascriptException

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

lastRunCrashID is in crashreporter code, which we don't build on ASAN.
http://hg.mozilla.org/mozilla-central/file/9c5d494d0548/build/unix/mozconfig.asan#l24

Can we maybe silently ignore the failure? I'm not sure what other test harnesses do to avoid issues. Ted, any thoughts?

https://treeherder.mozilla.org/logviewer.html#?job_id=156524&repo=ash

09:18:24     INFO -  Initial Profile Destination is "/tmp/tmpqPI5PQ.mozrunner"
09:18:24     INFO -  starting httpd
09:18:24     INFO -  running httpd on http://127.0.0.1:32784/
09:18:25     INFO -  Failure during test execution.
09:18:25     INFO -  Traceback (most recent call last):
09:18:25     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/runtests.py", line 68, in run
09:18:25     INFO -      runner.run_tests(tests)
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py", line 872, in run_tests
09:18:25     INFO -      self.add_test(test)
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py", line 1013, in add_test
09:18:25     INFO -      e10s = self.appinfo.get('browserTabsRemoteAutostart', False)
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py", line 677, in appinfo
09:18:25     INFO -      }""")
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1669, in execute_script
09:18:25     INFO -      rv = self._send_message("executeScript", body, key="value")
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
09:18:25     INFO -      return func(*args, **kwargs)
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 757, in _send_message
09:18:25     INFO -      self._handle_error(err)
09:18:25     INFO -    File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 818, in _handle_error
09:18:25     INFO -      raise errors.lookup(error)(message, stacktrace=stacktrace)
09:18:25    ERROR -  JavascriptException: JavascriptException: [Exception... "Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIXULRuntime.lastRunCrashID]"  nsresult: "0x80004001 (NS_ERROR_NOT_IMPLEMENTED)"  location: "JS frame :: chrome://marionette/content/element.js :: EM_wrapValue :: line 229"  data: no]
09:18:25     INFO -  stacktrace:
09:18:25     INFO -  	execute_script @base.py, line 677
09:18:25     INFO -  	inline javascript, line 229
09:18:25     INFO -  	src: "undefined"
09:18:25     INFO -  	Stack:
09:18:25     INFO -  	EM_wrapValue@chrome://marionette/content/element.js:229:13
09:18:25     INFO -  	GeckoDriver.prototype.executeScriptInSandbox@chrome://marionette/content/driver.js:829:23
09:18:25     INFO -  	GeckoDriver.prototype.execute@chrome://marionette/content/driver.js:920:5
09:18:25     INFO -  	TaskImpl_run@resource://gre/modules/Task.jsm:319:40
09:18:25     INFO -  	TaskImpl@resource://gre/modules/Task.jsm:280:3
09:18:25     INFO -  	createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
09:18:25     INFO -  	Task_spawn@resource://gre/modules/Task.jsm:168:12
09:18:25     INFO -  	TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:388:16
09:18:25     INFO -  	TaskImpl_run@resource://gre/modules/Task.jsm:327:13
09:18:25     INFO -  	TaskImpl@resource://gre/modules/Task.jsm:280:3
09:18:25     INFO -  	createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
09:18:25     INFO -  	Task_spawn@resource://gre/modules/Task.jsm:168:12
09:18:25     INFO -  	Dispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13
09:18:25     INFO -  	Dispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5
09:18:25     INFO -  	DebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9
09:18:25     INFO -  	exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
09:18:25     INFO -  	exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
09:18:25    ERROR -  {"thread": "MainThread", "level": "ERROR", "pid": 1915, "source": "Marionette test runner", "time": 1458317905062, "action": "log", "message": "Failure during harness setup", "stack": "Traceback (most recent call last):\n\n  File \"/builds/slave/test/build/tests/marionette/marionette/runtests.py\", line 88, in cli\n    failed = harness_class(runner_class, parser_class, args=args).run()\n\n  File \"/builds/slave/test/build/tests/marionette/marionette/runtests.py\", line 68, in run\n    runner.run_tests(tests)\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py\", line 872, in run_tests\n    self.add_test(test)\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py\", line 1013, in add_test\n    e10s = self.appinfo.get('browserTabsRemoteAutostart', False)\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py\", line 677, in appinfo\n    }\"\"\")\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 1669, in execute_script\n    rv = self._send_message(\"executeScript\", body, key=\"value\")\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/decorators.py\", line 36, in _\n    return func(*args, **kwargs)\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 757, in _send_message\n    self._handle_error(err)\n\n  File \"/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 818, in _handle_error\n    raise errors.lookup(error)(message, stacktrace=stacktrace)\n\nJavascriptException: JavascriptException: [Exception... \"Component returned failure code: 0x80004001 (NS_ERROR_NOT_IMPLEMENTED) [nsIXULRuntime.lastRunCrashID]\"  nsresult: \"0x80004001 (NS_ERROR_NOT_IMPLEMENTED)\"  location: \"JS frame :: chrome://marionette/content/element.js :: EM_wrapValue :: line 229\"  data: no]\nstacktrace:\n\texecute_script @base.py, line 677\n\tinline javascript, line 229\n\tsrc: \"undefined\"\n\tStack:\n\tEM_wrapValue@chrome://marionette/content/element.js:229:13\n\tGeckoDriver.prototype.executeScriptInSandbox@chrome://marionette/content/driver.js:829:23\n\tGeckoDriver.prototype.execute@chrome://marionette/content/driver.js:920:5\n\tTaskImpl_run@resource://gre/modules/Task.jsm:319:40\n\tTaskImpl@resource://gre/modules/Task.jsm:280:3\n\tcreateAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14\n\tTask_spawn@resource://gre/modules/Task.jsm:168:12\n\tTaskImpl_handleResultValue@resource://gre/modules/Task.jsm:388:16\n\tTaskImpl_run@resource://gre/modules/Task.jsm:327:13\n\tTaskImpl@resource://gre/modules/Task.jsm:280:3\n\tcreateAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14\n\tTask_spawn@resource://gre/modules/Task.jsm:168:12\n\tDispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13\n\tDispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5\n\tDebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9\n\texports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14\n\texports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14\n\n\n"}
09:18:25    ERROR - Return code: 1

Comment 1

[(not currently active) Ted Mielczarek]

I cannot for the life of me figure out where in the Marionette code this gets called. I assume this is just the Marionette test harness trying to use this unconditionally regardless of whether crash reporting is disabled, and other harnesses just don't do that.

Comment 2

[Andreas Tolfsen ❲:ato❳]

It looks like the actual script that is evaluated is this: https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/harness/marionette/runner/base.py#L672

Comment 3

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

(In reply to Andreas Tolfsen ‹:ato› from comment #2)
> It looks like the actual script that is evaluated is this:
> https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/harness/
> marionette/runner/base.py#L672

Yeah, I added that a few weeks ago in bug 1253618, but I don't understand how it could lead to this exception on ASAN alone.

Comment 4

[(not currently active) Ted Mielczarek]

Oh! I see what's happening. You're returning `Services.appInfo` which is an XPCOM object, and then the Marionette code is calling wrap_value on it:
https://dxr.mozilla.org/mozilla-central/rev/494289c72ba3997183e7b5beaca3e0447ecaf96d/testing/marionette/element.js#195

That code is enumerating all the properties of the object and copying them to a new object, but that's not actually safe to do in the general case for XPCOM, because properties can throw when accessed. In this specific case, one of the properties of that object is "lastRunCrashID", which will throw if the build was built with --disable-crashreporter:
https://dxr.mozilla.org/mozilla-central/rev/494289c72ba3997183e7b5beaca3e0447ecaf96d/toolkit/xre/nsAppRunner.cpp#1081

We're only seeing this on ASAN builds because those are the only builds we do in CI that --disable-crashreporter and run tests.

The right fix here is probably to fix wrap_value to have a try/catch around the property enumeration bits.

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Maja, is comment 4 something you're able to work with?

Comment 6

[Ryan VanderMeulen [:RyanVM]]

We could probably simulate these builds well enough on Try by just setting --disable-crashreporter in mozconfig.common.override on a regular Linux64 opt build. In fact, just for kicks...
https://treeherder.mozilla.org/#/jobs?repo=try&revision=16f58ac41f67

Comment 7

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #5)
> Maja, is comment 4 something you're able to work with?

Yes. I'm not familiar with the Marionette server stuff yet, but this sounds straightforward. Thanks for reminding me; added to my to-do list. :)

Comment 8

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Ryan, the call to appInfo got removed by ahal recently [1] so I'm assuming you don't see this issue anymore. Could you confirm?

Regardless, I'll follow-up on Ted's suggestion.

[1] https://hg.mozilla.org/mozilla-central/diff/940686f9541f/testing/marionette/harness/marionette/runner/base.py#l1.111

Comment 9

[Ryan VanderMeulen [:RyanVM]]

No, it's still reproducing on Ash.
https://treeherder.mozilla.org/logviewer.html#?job_id=167918&repo=ash

Comment 10

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Attachment: MozReview Request: Bug 1257922 - Marionette runs on ASAN fail due to fatal NS_ERROR_NOT_IMPLEMENTED JavascriptException; r?AutomatedTester

Review commit: https://reviewboard.mozilla.org/r/49813/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/49813/

Comment 11

[David Burns :automatedtester]

Comment on attachment 8747298 [details]
MozReview Request: Bug 1257922 - Marionette runs on ASAN fail due to fatal NS_ERROR_NOT_IMPLEMENTED JavascriptException; r?AutomatedTester

https://reviewboard.mozilla.org/r/49813/#review46553

::: testing/marionette/element.js:231
(Diff revision 1)
>          else {
>            result = {};
>            for (let prop in val) {
> +            try {
> -            result[prop] = this.wrapValue(val[prop]);
> +              result[prop] = this.wrapValue(val[prop]);
> +            } catch (e if (e.result == Components.results.NS_ERROR_NOT_IMPLEMENTED)) {

Can you add `results: Cr` to https://dxr.mozilla.org/mozilla-central/source/testing/marionette/element.js#7

then this line can be changed to 

`(e.result == Cr.NS_ERROR_NOT_IMPLEMENTED)`

Comment 12

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Comment on attachment 8747298 [details]
MozReview Request: Bug 1257922 - Marionette runs on ASAN fail due to fatal NS_ERROR_NOT_IMPLEMENTED JavascriptException; r?AutomatedTester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/49813/diff/1-2/

Comment 13

[David Burns :automatedtester]

Comment on attachment 8747298 [details]
MozReview Request: Bug 1257922 - Marionette runs on ASAN fail due to fatal NS_ERROR_NOT_IMPLEMENTED JavascriptException; r?AutomatedTester

https://reviewboard.mozilla.org/r/49813/#review46557

Comment 14

[Maja Frydrychowicz :impossibus (was :maja_zf) (needinfo me)]

Works locally. Try with --disable-crashreporter: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a392a21bcd27

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c0e34e377be4

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c0e34e377be4

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/03754c55722d