Closed Bug 1489628 Opened 7 years ago Closed 5 years 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 Client and Harness, 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: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
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: 6 years ago6 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years 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: 6 years ago5 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.