Closed Bug 1507372 Opened 4 years ago Closed 3 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Categories

(Testing :: Marionette, defect, P5)

Version 3
defect

Tracking

(firefox66 affected)

RESOLVED INCOMPLETE
Tracking Status
firefox66 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=211855446&repo=autoland

https://queue.taskcluster.net/v1/task/B1UchMaQRzid7rcD1DS3sw/runs/0/artifacts/public/logs/live_backing.log

17:50:50     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_current_position_and_size

17:58:04     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
17:58:04     INFO - Traceback (most recent call last):
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
17:58:04     INFO -     testMethod()
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 152, in test_move_to_negative_coordinates
17:58:04     INFO -     new_position = self.marionette.set_window_rect(x=-8, y=-8)
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1386, in set_window_rect
17:58:04     INFO -     body)
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
17:58:04     INFO -     m._handle_socket_failure()
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 844, in _handle_socket_failure
17:58:04     INFO -     reraise(IOError, message.format(returncode=returncode, reason=val), tb)
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
17:58:04     INFO -     return func(*args, **kwargs)
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 756, in _send_message
17:58:04     INFO -     msg = self.client.request(name, params)
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
17:58:04     INFO -     return self.receive()
17:58:04     INFO -   File "/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
17:58:04     INFO -     raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
17:58:04     INFO - TEST-INFO took 431610ms
17:58:04    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_rect.TestWindowRect", "method_name": "test_move_to_negative_coordinates"}, "expected": "PASS", "test": "testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n  File \"/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py\", line 190, in run\n    self.tearDown()\n  File \"/Users/cltbld/tasks/task_1542246181/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py\", line 39, in tearDown\n    self.marionette.set_window_rect(x=x, y=y, height=height, width=width)\n  File \"/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 1386, in set_window_rect\n    body)\n  File \"/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py\", line 26, in _\n    return func(*args, **kwargs)\n  File \"/Users/cltbld/tasks/task_1542246181/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py\", line 753, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n"}
17:58:04     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_resize_larger_than_screen
17:58:04     INFO - Application command: /Users/cltbld/tasks/task_1542246181/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox -no-remote -marionette -foreground -profile /var/folders/v2/hzw0fmpd0zd6rkgm86qttq5h00000x/T/tmpucVfmo.mozrunner
17:58:04     INFO -  *** You are running in headless mode.
17:58:06     INFO -  1542247086181	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: resource://pdf.js/
17:58:06     INFO -  1542247086182	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: about:reader*
17:58:06     INFO -  [1878, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
17:58:06     INFO -  [1878, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
17:58:06     INFO -  [1878, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
17:58:06     INFO -  [1878, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
17:58:06     INFO -  1542247086640	Marionette	DEBUG	Received observer notification profile-after-change
17:58:06     INFO -  [1878, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 2935
17:58:06     INFO -  1542247086763	Marionette	DEBUG	Received observer notification command-line-startup
17:58:06     INFO -  1542247086763	Marionette	DEBUG	Received observer notification nsPref:changed
17:58:06     INFO -  1542247086764	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
17:58:06     INFO -  ++DOCSHELL 0x11983a000 == 1 [pid = 1878] [id = {88270463-0f75-3948-aafa-27526e505aa6}]
It's a hang in "WebDriver:SetWindowRect" on OS X with the following parameters:

> 17:50:53     INFO -  1542246653612	Marionette	TRACE	102 -> [0,9,"WebDriver:SetWindowRect",{"y":-8,"x":-8,"width":null,"height":null}]

We need a fix for bug 1489955.
Depends on: 1489955
Over the last 7 days there are 52 failures on this bug, these happen on linux64, osx-10-10, windows10-64

Here is the most recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=213555752&repo=mozilla-inbound&lineNumber=31726
Flags: needinfo?(dburns)
Andreas can you have a look?

There appears to be a large number of these crashes happening on headless mode. I am not sure if we should be supporting this feature there or not. Can you also see if you can see what is the cause of the crash so we can get that underlying issue fixed.
Flags: needinfo?(dburns) → needinfo?(ato)
(In reply to David Burns :automatedtester from comment #6)
> There appears to be a large number of these crashes happening on headless
> mode. I am not sure if we should be supporting this feature there or not.
> Can you also see if you can see what is the cause of the crash so we can get
> that underlying issue fixed.

Note that this is not a crash, but an expected shutdown of the application because `WebDriver:SetWindowRect` hangs. This is on file as bug 1489955 and already marked as blocker for this bug.

As such the need-info request should be moved to the other bug.
Flags: needinfo?(ato)
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Even with bug 1478358 landed on January the 14th the "WebDriver:SetWindowRect" command hangs here, which is kinda scary. I will leave this bug open for now, and will revisit in a week or so.

Depends on: 1478358

No more such failures. So lets close as WFM. Feel free to reopen if it happens again.

Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → WORKSFORME

Fail reappeared on m-c.
Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=233527740&repo=mozilla-central&lineNumber=34246

Log snippet:

01:31:08 INFO - --DOMWINDOW == 44 (0000018CF9B8A000) [pid = 5012] [serial = 196] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 43 (0000018CFD073000) [pid = 5012] [serial = 194] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
01:31:08 INFO - --DOMWINDOW == 42 (0000018CFCD93800) [pid = 5012] [serial = 188] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 41 (0000018CFD073800) [pid = 5012] [serial = 234] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
01:31:08 INFO - --DOMWINDOW == 40 (0000018CFAD2D800) [pid = 5012] [serial = 230] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 39 (0000018CFCD86400) [pid = 5012] [serial = 220] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
01:31:08 INFO - --DOMWINDOW == 38 (0000018CFCD6E000) [pid = 5012] [serial = 219] [outer = 0000000000000000] [url = chrome://marionette/content/test_nested_iframe.xul]
01:31:08 INFO - --DOMWINDOW == 37 (0000018CFD06D000) [pid = 5012] [serial = 218] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
01:31:08 INFO - --DOMWINDOW == 36 (0000018CFCD63C00) [pid = 5012] [serial = 214] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 35 (0000018CFAD33400) [pid = 5012] [serial = 235] [outer = 0000000000000000] [url = chrome://marionette/content/test_nested_iframe.xul]
01:31:08 INFO - --DOMWINDOW == 34 (0000018CF917F800) [pid = 5012] [serial = 206] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 33 (0000018CF73A0400) [pid = 5012] [serial = 208] [outer = 0000000000000000] [url = about:blank]
01:31:08 INFO - --DOMWINDOW == 32 (0000018CFC4EB400) [pid = 5012] [serial = 236] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
01:32:49 INFO - [Parent 5012, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x18cf868d710 (http://mzl.la/1FuID0j).: file z:/build/build/src/storage/mozStoragePrivateHelpers.cpp, line 108
01:34:17 INFO - [Parent 5012, StreamTrans #60] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
01:34:17 INFO - [Parent 5012, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 993
01:36:17 INFO - [Parent 5012, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 114
01:36:17 INFO - [Parent 5012, Main Thread] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp, line 757
01:36:32 INFO - 1552440991997 Marionette DEBUG Closed connection 89
01:37:43 ERROR - TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_window_rect.py TestWindowRect.test_move_to_negative_coordinates | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
01:37:43 INFO - Traceback (most recent call last):
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
01:37:43 INFO - testMethod()
01:37:43 INFO - File "Z:\task_1552437914\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_window_rect.py", line 152, in test_move_to_negative_coordinates
01:37:43 INFO - new_position = self.marionette.set_window_rect(x=-8, y=-8)
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1220, in set_window_rect
01:37:43 INFO - body)
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
01:37:43 INFO - m._handle_socket_failure()
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\marionette.py", line 678, in _handle_socket_failure
01:37:43 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
01:37:43 INFO - return func(*args, **kwargs)
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\marionette.py", line 590, in _send_message
01:37:43 INFO - msg = self.client.request(name, params)
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\transport.py", line 273, in request
01:37:43 INFO - return self.receive()
01:37:43 INFO - File "Z:\task_1552437914\build\venv\lib\site-packages\marionette_driver\transport.py", line 183, in receive
01:37:43 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
01:37:43 INFO - TEST-INFO took 431211ms

Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE

This is still happening.

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=264594259&repo=mozilla-esr68&lineNumber=33024

16:14:27 INFO - --DOMWINDOW == 29 (0x129be5c00) [pid = 1635] [serial = 206] [outer = 0x0] [url = about:blank]
16:14:27 INFO - --DOMWINDOW == 28 (0x129b65400) [pid = 1635] [serial = 210] [outer = 0x0] [url = about:blank]
16:14:27 INFO - --DOMWINDOW == 27 (0x129b0d800) [pid = 1635] [serial = 230] [outer = 0x0] [url = about:blank]
16:14:27 INFO - --DOMWINDOW == 26 (0x129b5bc00) [pid = 1635] [serial = 218] [outer = 0x0] [url = about:blank]
16:15:51 INFO - [Parent 1635, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x12b6791b0 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 108
16:17:18 INFO - [Parent 1635, StreamTrans #8] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 371
16:17:18 INFO - [Parent 1635, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 994
16:20:00 INFO - 1567441200879 Marionette DEBUG Closed connection 90
16:21:15 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
16:21:15 INFO - Traceback (most recent call last):
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
16:21:15 INFO - testMethod()
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 152, in test_move_to_negative_coordinates
16:21:15 INFO - new_position = self.marionette.set_window_rect(x=-8, y=-8)
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1220, in set_window_rect
16:21:15 INFO - body)
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
16:21:15 INFO - m._handle_socket_failure()
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 678, in _handle_socket_failure
16:21:15 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
16:21:15 INFO - return func(*args, **kwargs)
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 590, in _send_message
16:21:15 INFO - msg = self.client.request(name, params)
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
16:21:15 INFO - return self.receive()
16:21:15 INFO - File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
16:21:15 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
16:21:15 INFO - TEST-INFO took 435144ms
16:21:15 ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_rect.TestWindowRect", "method_name": "test_move_to_negative_coordinates"}, "expected": "PASS", "test": "testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_move_to_negative_coordinates", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run\n self.tearDown()\n File "/Users/cltbld/tasks/task_1567440337/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 39, in tearDown\n self.marionette.set_window_rect(x=x, y=y, height=height, width=width)\n File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1220, in set_window_rect\n body)\n File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _\n return func(*args, **kwargs)\n File "/Users/cltbld/tasks/task_1567440337/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 587, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n"}
16:21:15 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_resize_larger_than_screen

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

The problem here are most likely the following two lines:

16:17:18 INFO - [Parent 1635, StreamTrans #8] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 371
16:17:18 INFO - [Parent 1635, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 994

Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.