Closed Bug 1509224 Opened 6 years ago Closed 6 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: 6 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.