Closed Bug 1489628 Opened 2 years ago Closed 3 months ago

Intermittent tests/unit/test_window_rect.py TestWindowRect.test_get_types | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)

Categories

(Testing :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: ncsoregi [at] mozilla.com

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

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

11:26:58     INFO -  --DOMWINDOW == 55 (0x126c82400) [pid = 703] [serial = 288] [outer = 0x0] [url = chrome://browser/content/browser.xul]
11:26:58     INFO -  --DOMWINDOW == 54 (0x12854ca00) [pid = 703] [serial = 290] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 53 (0x12917d400) [pid = 703] [serial = 250] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 52 (0x12b2dbc00) [pid = 703] [serial = 246] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 51 (0x134679000) [pid = 703] [serial = 276] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 50 (0x132e05400) [pid = 703] [serial = 272] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 49 (0x116235c00) [pid = 703] [serial = 232] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 48 (0x12ff7b400) [pid = 703] [serial = 242] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 47 (0x129183000) [pid = 703] [serial = 238] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 46 (0x126b84400) [pid = 703] [serial = 219] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 45 (0x109e7a000) [pid = 703] [serial = 213] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 44 (0x1331bdc00) [pid = 703] [serial = 267] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 43 (0x12eca4400) [pid = 703] [serial = 263] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 42 (0x12b2db000) [pid = 703] [serial = 244] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 41 (0x1331c7400) [pid = 703] [serial = 293] [outer = 0x0] [url = about:blank]
11:27:07     INFO -  --DOMWINDOW == 40 (0x1331c2c00) [pid = 703] [serial = 289] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 39 (0x109e80c00) [pid = 703] [serial = 211] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 38 (0x12eddf800) [pid = 703] [serial = 241] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 37 (0x132e0cc00) [pid = 703] [serial = 249] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 36 (0x12a88a000) [pid = 703] [serial = 253] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 35 (0x132e10000) [pid = 703] [serial = 252] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 34 (0x132e04c00) [pid = 703] [serial = 261] [outer = 0x0] [url = chrome://marionette/content/test_nested_iframe.xul]
11:27:09     INFO -  --DOMWINDOW == 33 (0x132e02c00) [pid = 703] [serial = 260] [outer = 0x0] [url = chrome://marionette/content/test2.xul]
11:27:09     INFO -  --DOMWINDOW == 32 (0x132e02800) [pid = 703] [serial = 259] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 31 (0x116233400) [pid = 703] [serial = 255] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 30 (0x1331c3000) [pid = 703] [serial = 266] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 29 (0x12ff84000) [pid = 703] [serial = 270] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 28 (0x116235400) [pid = 703] [serial = 269] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 27 (0x134679c00) [pid = 703] [serial = 275] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 26 (0x132e0e400) [pid = 703] [serial = 279] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 25 (0x13467c800) [pid = 703] [serial = 278] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 24 (0x1331c6000) [pid = 703] [serial = 287] [outer = 0x0] [url = chrome://marionette/content/test_nested_iframe.xul]
11:27:09     INFO -  --DOMWINDOW == 23 (0x1331bfc00) [pid = 703] [serial = 286] [outer = 0x0] [url = chrome://marionette/content/test2.xul]
11:27:09     INFO -  --DOMWINDOW == 22 (0x1331bb000) [pid = 703] [serial = 285] [outer = 0x0] [url = about:blank]
11:27:09     INFO -  --DOMWINDOW == 21 (0x132e10400) [pid = 703] [serial = 281] [outer = 0x0] [url = about:blank]
11:28:12     INFO -  --DOMWINDOW == 20 (0x1346f0400) [pid = 703] [serial = 294] [outer = 0x0] [url = about:blank]
11:28:12     INFO -  --DOMWINDOW == 19 (0x128139000) [pid = 703] [serial = 291] [outer = 0x0] [url = about:blank]
11:28:24     INFO -  --DOMWINDOW == 18 (0x13467fc00) [pid = 703] [serial = 295] [outer = 0x0] [url = about:blank]
11:28:24     INFO -  --DOMWINDOW == 17 (0x1331bb800) [pid = 703] [serial = 296] [outer = 0x0] [url = about:blank]
11:28:24     INFO -  --DOMWINDOW == 16 (0x13467b000) [pid = 703] [serial = 292] [outer = 0x0] [url = about:blank]
11:30:26     INFO -  [Parent 703, StreamTrans #60] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 417
11:30:26     INFO -  [Parent 703, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1125
11:32:47     INFO -  1536345167755	Marionette	DEBUG	Closed connection 97
11:34:43     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_get_types | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
11:34:43     INFO - Traceback (most recent call last):
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 140, in run
11:34:43     INFO -     self.setUp()
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 33, in setUp
11:34:43     INFO -     self.marionette.set_window_rect(height=start_size["height"], width=start_size["width"])
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1357, in set_window_rect
11:34:43     INFO -     body)
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 31, in _
11:34:43     INFO -     m._handle_socket_failure()
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 839, in _handle_socket_failure
11:34:43     INFO -     reraise(IOError, message.format(returncode=returncode, reason=val), tb)
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
11:34:43     INFO -     return func(*args, **kwargs)
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 751, in _send_message
11:34:43     INFO -     msg = self.client.request(name, params)
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
11:34:43     INFO -     return self.receive()
11:34:43     INFO -   File "/Users/cltbld/tasks/task_1536344366/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
11:34:43     INFO -     raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
11:34:43     INFO - TEST-INFO took 481605ms
Hang in command `WebDriver:SetWindowRect`:

> 11:26:42     INFO -  1536344802211	Marionette	TRACE	97 -> [0,5,"WebDriver:GetWindowRect",{}]
> 11:26:42     INFO -  1536344802213	Marionette	TRACE	97 <- [1,5,null,{"x":4,"y":4,"width":1366,"height":768,"state":"maximized"}]
> 11:26:42     INFO -  1536344802216	Marionette	TRACE	97 -> [0,6,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness ... width: window.screen.availWidth,\n              height: window.screen.availHeight,\n            }","sandbox":null,"line":22}]
> 11:26:42     INFO -  1536344802233	Marionette	TRACE	97 <- [1,6,null,{"value":{"width":1366,"height":768}}]
> 11:26:42     INFO -  1536344802237	Marionette	TRACE	97 -> [0,7,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1356,"height":758}]

It depends on bug 1489955.
Depends on: 1489955
Should be fixed by bug 1489955.
Assignee: nobody → ato
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
Fail reappeared on autoland.
Log link: https://treeherder.mozilla.org/logviewer.html#?job_id=212072680&repo=autoland&lineNumber=33461
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla65 → ---
It's a hang in "WebDriver:SetWindowRect":

> TRACE   88 -> [0,5,"WebDriver:GetWindowRect",{}]
> TRACE   88 <- [1,5,null,{"x":-8,"y":-8,"width":1040,"height":784,"state":"maximized"}]
> TRACE   88 -> [0,6,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"Z:\\task_1542319410\\build\\test ... width: window.screen.availWidth,\n              height: window.screen.availHeight,\n            }","sandbox":null,"line":22}]
> TRACE   88 <- [1,6,null,{"value":{"width":1024,"height":768}}]
> TRACE   88 -> [0,7,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1040,"height":784}]
> TRACE   88 <- [1,7,null,{"x":4,"y":4,"width":1040,"height":784,"state":"normal"}]

This call should only resize the window but actually moves it by 12px in x and y direction. Why that?

> TRACE   88 -> [0,8,"WebDriver:GetWindowRect",{}]
> TRACE   88 <- [1,8,null,{"x":4,"y":4,"width":1040,"height":784,"state":"normal"}]
> TRACE   88 -> [0,9,"WebDriver:SetWindowRect",{"y":-8,"x":-8,"width":1040,"height":784}]

So this fails moving it back to the former position.
Flags: needinfo?(ato)
Windows offsets the windows off the left hand side and the top by
a certain number of pixels when the window is maximised.  Resizing
the window will cause those offset window borders to be moved inside
the screen boundaries again.  This part of the trace log are clear
and expected.

What is not clear is why the last call (request no. 9 on connection
88) hangsand never returns.  I suspect it is because test_window_rect.py
records the original start position, which is maximised with a X/Y
position of -8 px and tries using that.  That means there are two
problems here:

  (1) The test sometimes ends up starting with a maximised window,
      and the test should ensure the window isn’t maximised.

  (2) Marionette needs to deal with unreachable/negative X/Y
      positions.

We have a solution for 1 in WPT, so possibly the right thing to do
here is port whatever remaining tests we have in test_window_rect.py
over to WPT and add a new test + a fix for 2.
Flags: needinfo?(ato)
Assignee: ato → nobody
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=270099986&repo=mozilla-esr68&lineNumber=34867

17:06:09 INFO - --DOMWINDOW == 35 (000002DE6B4A4C00) [pid = 6948] [serial = 245] [outer = 0000000000000000] [url = chrome://marionette/content/test2.xul]
17:06:09 INFO - --DOMWINDOW == 34 (000002DE5EE94400) [pid = 6948] [serial = 215] [outer = 0000000000000000] [url = about:blank]
17:06:09 INFO - --DOMWINDOW == 33 (000002DE64F6F000) [pid = 6948] [serial = 207] [outer = 0000000000000000] [url = about:blank]
17:06:09 INFO - --DOMWINDOW == 32 (000002DE638AC000) [pid = 6948] [serial = 217] [outer = 0000000000000000] [url = about:blank]
17:06:09 INFO - --DOMWINDOW == 31 (000002DE6AC03000) [pid = 6948] [serial = 219] [outer = 0000000000000000] [url = about:blank]
17:06:09 INFO - --DOMWINDOW == 30 (000002DE6A012800) [pid = 6948] [serial = 177] [outer = 0000000000000000] [url = about:blank]
17:06:47 INFO - --DOMWINDOW == 29 (000002DE69444A60) [pid = 6948] [serial = 230] [outer = 0000000000000000] [url = chrome://browser/content/browser.xul]
17:06:47 INFO - --DOMWINDOW == 28 (000002DE65B80E20) [pid = 6948] [serial = 246] [outer = 0000000000000000] [url = chrome://browser/content/browser.xul]
17:06:47 INFO - --DOMWINDOW == 27 (000002DE62B1E4C0) [pid = 6948] [serial = 234] [outer = 0000000000000000] [url = chrome://browser/content/browser.xul]
17:06:55 INFO - --DOMWINDOW == 26 (000002DE69AF9800) [pid = 6948] [serial = 231] [outer = 0000000000000000] [url = about:blank]
17:06:55 INFO - --DOMWINDOW == 25 (000002DE6C577800) [pid = 6948] [serial = 247] [outer = 0000000000000000] [url = about:blank]
17:06:55 INFO - --DOMWINDOW == 24 (000002DE5EFF3400) [pid = 6948] [serial = 235] [outer = 0000000000000000] [url = about:blank]
17:07:35 INFO - [Parent 6948, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x2de67720aa0 (http://mzl.la/1FuID0j).: file z:/build/build/src/storage/mozStoragePrivateHelpers.cpp, line 108
17:09:04 INFO - [Parent 6948, StreamTrans #6] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
17:09:04 INFO - [Parent 6948, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
17:11:30 INFO - 1570468290164 Marionette DEBUG Closed connection 86
17:12:41 ERROR - TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_window_rect.py TestWindowRect.test_get_types | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
17:12:41 INFO - Traceback (most recent call last):
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 140, in run
17:12:41 INFO - self.setUp()
17:12:41 INFO - File "Z:\task_1570464700\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_window_rect.py", line 33, in setUp
17:12:41 INFO - self.marionette.set_window_rect(height=start_size["height"], width=start_size["width"])
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1220, in set_window_rect
17:12:41 INFO - body)
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
17:12:41 INFO - m._handle_socket_failure()
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\marionette.py", line 678, in _handle_socket_failure
17:12:41 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
17:12:41 INFO - return func(*args, **kwargs)
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\marionette.py", line 590, in _send_message
17:12:41 INFO - msg = self.client.request(name, params)
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\transport.py", line 273, in request
17:12:41 INFO - return self.receive()
17:12:41 INFO - File "Z:\task_1570464700\build\venv\lib\site-packages\marionette_driver\transport.py", line 183, in receive
17:12:41 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))

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