Closed Bug 1507372 Opened 6 years ago Closed 5 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 Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Type:
defect

Tracking

(firefox66 affected)

Status:
RESOLVED INCOMPLETE
Tracking Flags:
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)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=222230563&repo=autoland&lineNumber=32431

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.

status-firefox66: --- → affected
Depends on: 1478358

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

Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 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 → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 6 years ago → 5 years ago
Resolution: --- → INCOMPLETE

New failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=256032225&repo=autoland&lineNumber=35109

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 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.