1140542 - Marionette screenshot failure results in a stack trace before actual error stack trace

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Nils Ohlmeier [:drno]]

Sometimes we encounter errors where marionette seems to try to make a screenshot as part of gathering the debug information, but then fails to make that screenshot (maybe because the browser is closed already?). It would be nice to not get a stack dump for that failure, but just some log message or so.

+ python /home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/marionette/runtests.py --type=browser --binary=/home/mozilla/jenkins/workspace/hello-e2e-marionette/firefox/firefox /home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/manifest.ini
starting httpd
running webserver on http://127.0.0.1:38652/
mozversion application_buildid: 20150304030231
mozversion application_changeset: c5b90c003be8
mozversion application_display_name: Nightly
mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
mozversion application_name: Firefox
mozversion application_remotingname: firefox
mozversion application_repository: https://hg.mozilla.org/mozilla-central
mozversion application_vendor: Mozilla
mozversion application_version: 39.0a1
mozversion platform_buildid: 20150304030231
mozversion platform_changeset: c5b90c003be8
mozversion platform_repository: https://hg.mozilla.org/mozilla-central
mozversion platform_version: 39.0a1
SUITE-START | Running 1 tests
TEST-START | test_1_browser_call.py Test1BrowserCall.test_1_browser_call
node server.js
Static contents are available at http://localhost:3001/content/
Tests are viewable at http://localhost:3001/test/
Use this for development only.
Thu, 05 Mar 2015 11:46:54 GMT express deprecated req.param(name): Use req.params, req.body, or req.query instead at loop/routes/validators.js:233:21
Failed to gather test failure debug.
Traceback (most recent call last):

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/marionette/runner/base.py", line 548, in gather_debug
   rv['screenshot'] = marionette.screenshot()

 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 1655, in screenshot
   full=full)

 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/decorators.py", line 36, in _
   return func(*args, **kwargs)

 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 670, in _send_message
   self._handle_error(response)

 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 699, in _handle_error
   "Malformed packet, expected key 'error' to be a dict: %s" % response)

MarionetteException: MarionetteException: Malformed packet, expected key 'error' to be a dict: {u'message': u'doc is undefined', u'error': u"error occurred while processing 'takeScreenshot"}


TEST-UNEXPECTED-ERROR | test_1_browser_call.py Test1BrowserCall.test_1_browser_call | TimeoutException: Traceback (most recent call last):
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/wait.py", line 122, in until
   rv = condition(self.marionette)
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 46, in <lambda>
   .until(lambda m: m.find_element(by, locator).is_displayed())
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 1448, in find_element
   response = self._send_message('findElement', 'value', **kwargs)
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/decorators.py", line 36, in _
   return func(*args, **kwargs)
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 670, in _send_message
   self._handle_error(response)
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 709, in _handle_error
   raise errors.NoSuchElementException(message=message, status=status, stacktrace=stacktrace)
TimeoutException: Timed out after 20.9 seconds, caused by <class 'marionette_driver.errors.NoSuchElementException'>


Traceback (most recent call last):
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/marionette/marionette_test.py", line 290, in run
   testMethod()
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 184, in test_1_browser_call
   self.standalone_check_remote_video()
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 145, in standalone_check_remote_video
   self.check_video(".remote .OT_subscriber .OT_widget-container")
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 136, in check_video
   selector, 20)
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 46, in wait_for_element_displayed
   .until(lambda m: m.find_element(by, locator).is_displayed())
 File "/home/mozilla/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/wait.py", line 143, in until
   cause=last_exc)
TEST-INFO took 153076ms

SUMMARY
-------
passed: 0
failed: 1
todo: 0

Comment 1

[Dave Hunt [:davehunt] [he/him] ⌚BST]

FYI, "Malformed packet, expected key 'error' to be a dict" has been resolved by https://hg.mozilla.org/mozilla-central/rev/e2358ee2e4c8 however its just a poor representation of the error - you'll still get the error. The debug should be gathered before the browser is closed - are you seeing a crash?

Comment 2

[Nils Ohlmeier [:drno]]

I know the "malformed packet" was a bad example. It was from an failure a couple of days ago. But here is a more recent example from a different failure.

+ python /home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/marionette/runtests.py --type=browser --binary=/home/mozilla/jenkins/workspace/hello-e2e-marionette/firefox/firefox /home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/manifest.ini
starting httpd
running webserver on http://127.0.0.1:54316/
mozversion application_buildid: 20150309030224
mozversion application_changeset: eab4a81e4457
mozversion application_display_name: Nightly
mozversion application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
mozversion application_name: Firefox
mozversion application_remotingname: firefox
mozversion application_repository: https://hg.mozilla.org/mozilla-central
mozversion application_vendor: Mozilla
mozversion application_version: 39.0a1
mozversion platform_buildid: 20150309030224
mozversion platform_changeset: eab4a81e4457
mozversion platform_repository: https://hg.mozilla.org/mozilla-central
mozversion platform_version: 39.0a1
SUITE-START | Running 1 tests
TEST-START | test_1_browser_call.py Test1BrowserCall.test_1_browser_call
node server.js
Static contents are available at http://localhost:3001/content/
Tests are viewable at http://localhost:3001/test/
Use this for development only.
Mon, 09 Mar 2015 13:42:22 GMT express deprecated req.param(name): Use req.params, req.body, or req.query instead at loop/routes/validators.js:233:21
Failed to gather test failure debug.
Traceback (most recent call last):

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/marionette/runner/base.py", line 548, in gather_debug
   rv['screenshot'] = marionette.screenshot()

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 1655, in screenshot
   full=full)

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/decorators.py", line 36, in _
   return func(*args, **kwargs)

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 670, in _send_message
   self._handle_error(response)

 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/venv/local/lib/python2.7/site-packages/marionette_driver-0.2-py2.7.egg/marionette_driver/marionette.py", line 755, in _handle_error
   raise errors.MarionetteException(message=message, status=status, stacktrace=stacktrace)

MarionetteException: MarionetteException: error occurred while processing 'takeScreenshot
stacktrace:
	doc is undefined



TEST-UNEXPECTED-FAIL | test_1_browser_call.py Test1BrowserCall.test_1_browser_call | AssertionError: room URL returned by server  has invalid scheme

Traceback (most recent call last):
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/venv/local/lib/python2.7/site-packages/marionette_client-0.9-py2.7.egg/marionette/marionette_test.py", line 290, in run
   testMethod()
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 172, in test_1_browser_call
   room_url = self.local_get_and_verify_room_url()
 File "/home/mozilla/jenkins/workspace/hello-e2e-marionette/marionette/tests/browser/components/loop/test/functional/test_1_browser_call.py", line 115, in local_get_and_verify_room_url
   " has invalid scheme")
TEST-INFO took 25008ms

Comment 3

[Andreas Tolfsen ❲:ato❳]

This can be reproduced running testing/marionette/client/marionette/tests/unit/test_window_type.py.  I was able to collect the following stacktrace:

1453904683148	Marionette	TRACE	conn3 -> [0,19,"takeScreenshot",{"highlights":null,"full":true,"id":null}]
*************************
A coding exception was thrown and uncaught in a Task.

Full message: TypeError: doc is undefined
Full stack: GeckoDriver.prototype.takeScreenshot@chrome://marionette/content/driver.js:2601:11
Dispatcher.prototype.execute/req<@chrome://marionette/content/dispatcher.js:126:20
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
Task_spawn@resource://gre/modules/Task.jsm:168:12
Dispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13
Dispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5
DebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14

Comment 4

[Andreas Tolfsen ❲:ato❳]

The test_window_type.py test will only fail if you have ac_add_options --disable-tests added to your mozconfig so that the text.xul resource is not included.

The root cause of this bug is obviously that we’re not getting the correct window or root document element.

Comment 5

[Andreas Tolfsen ❲:ato❳]

Attachment: MozReview Request: Bug 1140542 - Support capturing secondary chrome windows; r?automatedtester

A <window> object may not exist in popup windows that are spawned from
a <window>.  document.documentElement is equivalent to <window> in
the case of the primary window, but lets us support the ChromeWindow's
document when it isn't.

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

Comment 6

[Andreas Tolfsen ❲:ato❳]

It is likely that the new screen capture code in testing/marionette/capture.js would’ve solved this, if it was used for chrome as well.  It is currently only in use for content captures.  I’ve filed bug 1243415 to address this.

However, this isn’t a blocker for fixing chrome screenshots right away.

Comment 7

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8712713 [details]
MozReview Request: Bug 1140542 - Support capturing secondary chrome windows; r?automatedtester

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

Comment 8

[David Burns :automatedtester]

Comment on attachment 8712713 [details]
MozReview Request: Bug 1140542 - Support capturing secondary chrome windows; r?automatedtester

https://reviewboard.mozilla.org/r/32637/#review29369

Comment 9

[Pulsebot]

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

Comment 10

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 11

[Andreas Tolfsen ❲:ato❳]

Can you please confirm that the patch fixes your issue?

Comment 12

[Nils Ohlmeier [:drno]]

Not easy to reproduce. But a test failure from 2016-02-01 does not show this error any more. So I think it is properly fixed.