Closed Bug 1509224 Opened 5 years ago Closed 5 years ago

Intermittent testing\marionette\harness\marionette_harness\tests\unit\test_window_maximize.py TestWindowMaximize.test_maximize | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: hang, intermittent-failure)

Filed by: dluca [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/XA7V0aRnSuuJ9muS-Z-opQ/runs/0/artifacts/public/logs/live_backing.log

INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_window_maximize.py TestWindowMaximize.test_maximize
22:05:51     INFO -  1542837951843	Marionette	DEBUG	Closed connection 101
22:05:51     INFO -  1542837951847	Marionette	DEBUG	Accepted connection 102 from 127.0.0.1:51406
22:05:51     INFO -  1542837951849	Marionette	TRACE	102 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
22:05:51     INFO -  1542837951853	Marionette	DEBUG	[2147483899] Frame script loaded
22:05:51     INFO -  1542837951854	Marionette	DEBUG	[2147483899] Frame script registered
22:05:51     INFO -  1542837951857	Marionette	TRACE	102 <- [1,1,null,{"sessionId":"d52d2452-315a-4209-8c3d-1cf04e55d331","capabilities":{"browserName":"firefox","browserVersion":"65.0a ... p\\tmpwkgdto.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
22:05:51     INFO -  1542837951860	Marionette	TRACE	102 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
22:05:51     INFO -  1542837951861	Marionette	TRACE	102 <- [1,2,null,{"value":null}]
22:05:51     INFO -  1542837951863	Marionette	TRACE	102 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
22:05:51     INFO -  1542837951864	Marionette	TRACE	102 <- [1,3,null,{"value":null}]
22:05:51     INFO -  1542837951866	Marionette	TRACE	102 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
22:05:51     INFO -  1542837951867	Marionette	TRACE	102 <- [1,4,null,{"value":null}]
22:05:51     INFO -  1542837951869	Marionette	TRACE	102 -> [0,5,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"Z:\\task_1542836712\\build\\test ... width: window.screen.availWidth,\n              height: window.screen.availHeight,\n            }","sandbox":null,"line":18}]
22:05:51     INFO -  1542837951874	Marionette	TRACE	102 <- [1,5,null,{"value":{"width":1366,"height":768}}]
22:05:51     INFO -  1542837951876	Marionette	TRACE	102 -> [0,6,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1266,"height":668}]
22:05:52     INFO -  1542837952131	Marionette	TRACE	102 <- [1,6,null,{"x":4,"y":4,"width":1266,"height":668,"state":"normal"}]
22:05:52     INFO -  1542837952133	Marionette	TRACE	102 -> [0,7,"WebDriver:GetWindowRect",{}]
22:05:52     INFO -  1542837952134	Marionette	TRACE	102 <- [1,7,null,{"x":4,"y":4,"width":1266,"height":668,"state":"normal"}]
22:05:52     INFO -  1542837952136	Marionette	TRACE	102 -> [0,8,"WebDriver:MaximizeWindow",{}]
22:05:56     INFO -  1542837956637	Marionette	WARN	TimedPromise timed out after 4500 ms: stacktrace:
22:05:56     INFO -  bail@chrome://marionette/content/sync.js:196:64
22:10:24     INFO -  [Parent 7760, StreamTrans #89] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 434
22:10:24     INFO -  [Parent 7760, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 1142
22:11:52     INFO -  1542838312172	Marionette	DEBUG	Closed connection 102
22:13:03    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_window_maximize.py TestWindowMaximize.test_maximize | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
22:13:03     INFO -  Traceback (most recent call last):
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
22:13:03     INFO -      testMethod()
22:13:03     INFO -    File "Z:\task_1542836712\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_window_maximize.py", line 34, in test_maximize
22:13:03     INFO -      self.marionette.maximize_window()
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\marionette.py", line 2051, in maximize_window
22:13:03     INFO -      return self._send_message("WebDriver:MaximizeWindow")
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
22:13:03     INFO -      m._handle_socket_failure()
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\marionette.py", line 844, in _handle_socket_failure
22:13:03     INFO -      reraise(IOError, message.format(returncode=returncode, reason=val), tb)
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
22:13:03     INFO -      return func(*args, **kwargs)
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\marionette.py", line 756, in _send_message
22:13:03     INFO -      msg = self.client.request(name, params)
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\transport.py", line 273, in request
22:13:03     INFO -      return self.receive()
22:13:03     INFO -    File "Z:\task_1542836712\build\venv\lib\site-packages\marionette_driver\transport.py", line 183, in receive
22:13:03     INFO -      raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
22:13:03     INFO -  TEST-INFO took 431493ms
22:13:03     INFO -  test_end for testing\marionette\harness\marionette_harness\tests\unit\test_window_maximize.py TestWindowMaximize.test_maximize logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_maximize.TestWindowMaximize", "method_name": "test_maximize"}, "expected": "PASS", "test": "testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_window_maximize.py TestWindowMaximize.test_maximize", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n  File \"Z:\\task_1542836712\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 190, in run\n    self.tearDown()\n  File \"Z:\\task_1542836712\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_window_maximize.py\", line 31, in tearDown\n    width=self.original_size[\"width\"], height=self.original_size[\"height\"])\n  File \"Z:\\task_1542836712\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1386, in set_window_rect\n    body)\n  File \"Z:\\task_1542836712\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 26, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_1542836712\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 753, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n"}
22:13:03     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_window_status_content.py TestNoSuchWindowContent.test_closed_chrome_window
22:13:03     INFO -  Application command: Z:\task_1542836712\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1542836712\appdata\local\temp\tmp1s9hu3.mozrunner
22:13:03     INFO -  *** You are running in headless mode.
22:13:03     INFO -  [4264, Main Thread] WARNING: Failed to load startupcache file correctly, removing!: file z:/build/build/src/startupcache/StartupCache.cpp, line 216
22:13:04     INFO -  1542838384320	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: resource://pdf.js/
22:13:04     INFO -  1542838384320	addons.webextension.screenshots@mozilla.org	WARN	Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: about:reader*
22:13:04     INFO -  [4264, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
22:13:04     INFO -  [4264, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
22:13:04     INFO -  [4264, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
22:13:04     INFO -  [4264, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file z:/build/build/src/netwerk/protocol/res/SubstitutingProtocolHandler.cpp, line 342
22:13:04     INFO -  1542838384675	Marionette	DEBUG	Received observer notification profile-after-change
22:13:04     INFO -  [4264, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/extensions/cookie/nsPermissionManager.cpp, line 2935
22:13:04     INFO -  ++DOCSHELL 00000227573C3800 == 1 [pid = 4264] [id = {eed5f3b1-3793-4cba-9ce2-479598eabd2c}]
22:13:04     INFO -  ++DOMWINDOW == 1 (0000022756D89800) [pid = 4264] [serial = 1] [outer = 0000000000000000]
22:13:04     INFO -  ++DOMWINDOW == 2 (0000022756D8A000) [pid = 4264] [serial = 2] [outer = 0000022756D89800]
22:13:04     INFO -  1542838384727	Marionette	DEBUG	Received observer notification toplevel-window-ready
22:13:04     INFO -  1542838384797	Marionette	DEBUG	Received observer notification command-line-startup
22:13:04     INFO -  1542838384798	Marionette	DEBUG	Received observer notification nsPref:changed
22:13:04     INFO -  1542838384798	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
The command "WebDriver:MaximizeWindow" caused a socket timeout even with a TimedPromise timing out after 4.5s. As it looks like this error is not correctly bubbling up. It's most likely a problem for all the modified windows manipulation commands.

It's blocked by bug 1375185.

Andreas, can you please have a look, so that we can get rid of this hang? Thanks.
Severity: normal → critical
Flags: needinfo?(ato)
Keywords: hang
I can’t reproduce this and it doesn’t appear to happen very frequently
on central.

Next step is to do a try run on Windows 10 x64 headless, but the
trees are closed.
Failure persists very infrequently on windows10-64 so Ive done the
following try build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=91c5cb30733a80ce1dcccbd6b349494b042c9978
Flags: needinfo?(ato)
Status: NEW → RESOLVED
Closed: 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.