1411189 - Intermittent test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=139091475&repo=mozilla-inbound

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

05:12:46     INFO -  Application command: Z:\task_1508814915\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmpbu043v.mozrunner
05:12:47     INFO -  1508821967284	Marionette	DEBUG	Received observer notification "profile-after-change"
05:12:47     INFO -  1508821967371	Marionette	DEBUG	Received observer notification "command-line-startup"
05:12:47     INFO -  1508821967371	Marionette	INFO	Enabled via --marionette
05:14:47    ERROR -  TEST-UNEXPECTED-ERROR | test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
05:14:47     INFO -  Traceback (most recent call last):
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 187, in run
05:14:47     INFO -      self.tearDown()
05:14:47     INFO -    File "Z:\task_1508814915\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_cli_arguments.py", line 21, in tearDown
05:14:47     INFO -      super(TestCommandLineArguments, self).tearDown()
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 322, in tearDown
05:14:47     INFO -      self.marionette.start_session()
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_driver\decorators.py", line 23, in _
05:14:47     INFO -      return func(*args, **kwargs)
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1212, in start_session
05:14:47     INFO -      self.start_binary(timeout)
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_driver\marionette.py", line 633, in start_binary
05:14:47     INFO -      self.raise_for_port(timeout=timeout)
05:14:47     INFO -    File "Z:\task_1508814915\build\venv\lib\site-packages\marionette_driver\marionette.py", line 721, in raise_for_port
05:14:47     INFO -      self.host, self.port))
05:14:47     INFO -  TEST-INFO took 122389ms

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This happens after a restart. So it might become fixed once the patch on bug 1410366 lands.

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually this test is failing because there is no `sessionstore-windows-restored` notification. See bug 1382162.

Comment 3

[Intermittent Failures Robot]

1 failures in 912 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1411189&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 4

[Firefox Bug Husbandry Bot]

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

Comment 5

[Natalia Csoregi [:nataliaCs]]

https://treeherder.mozilla.org/logviewer.html#?job_id=160314749&repo=mozilla-central&lineNumber=1148

Comment 6

[Intermittent Failures Robot]

1 failures in 735 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1411189&startday=2018-01-29&endday=2018-02-04&tree=all

Comment 7

[Intermittent Failures Robot]

2 failures in 685 pushes (0.003 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2

Platform breakdown:
* windows10-64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1411189&startday=2018-02-12&endday=2018-02-18&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 831 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1411189&startday=2018-02-26&endday=2018-03-04&tree=all

Comment 9

[Firefox Bug Husbandry Bot]

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

Comment 10

[Andrei Ciure[:aciure]]

new occurrence:

03:06:14     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode
03:06:14     INFO -  1524279974818	Marionette	DEBUG	Accepted connection 12 from 127.0.0.1:49834
03:06:14     INFO -  1524279974819	Marionette	TRACE	12 -> [0,1,"WebDriver:NewSession",{}]
03:06:14     INFO -  1524279974820	Marionette	DEBUG	Register listener.js for window 2147483649
03:06:14     INFO -  1524279974823	Marionette	TRACE	12 <- [1,1,null,{"sessionId":"277a8783-f8ff-420c-be93-cb4aa431bf2f","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... 4279791\\AppData\\Local\\Temp\\tmpw3dsh4.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
03:06:14     INFO -  1524279974826	Marionette	TRACE	12 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
03:06:14     INFO -  1524279974826	Marionette	TRACE	12 <- [1,2,null,{}]
03:06:14     INFO -  1524279974827	Marionette	TRACE	12 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
03:06:14     INFO -  1524279974828	Marionette	TRACE	12 <- [1,3,null,{}]
03:06:14     INFO -  1524279974829	Marionette	TRACE	12 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
03:06:14     INFO -  1524279974829	Marionette	TRACE	12 <- [1,4,null,{}]
03:06:14     INFO -  1524279974830	Marionette	TRACE	12 -> [0,5,"WebDriver:DeleteSession",{}]
03:06:14     INFO -  1524279974833	Marionette	TRACE	12 <- [1,5,null,{}]
03:06:14     INFO -  Application command: Z:\task_1524279791\build\application\firefox\firefox.exe -no-remote -marionette -safe-mode -profile c:\users\task_1524279791\appdata\local\temp\tmpw3dsh4.mozrunner
03:06:15     INFO -  1524279975145	Marionette	DEBUG	Received observer notification profile-after-change
03:06:15     INFO -  1524279975183	Marionette	DEBUG	Received observer notification command-line-startup
03:06:15     INFO -  1524279975183	Marionette	DEBUG	Received observer notification nsPref:changed
03:06:15     INFO -  1524279975225	Marionette	DEBUG	Received observer notification domwindowopened
03:06:15     INFO -  1524279975289	Marionette	DEBUG	Safe mode detected, supressing dialog
03:06:16     INFO -  1524279976001	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
03:06:16     INFO -  1524279976617	Marionette	DEBUG	New connections are accepted
03:06:16     INFO -  1524279976618	Marionette	INFO	Listening on port 2828
03:06:16     INFO -  Unable to read VR Path Registry from Z:\task_1524279791\AppData\Local\openvr\openvrpaths.vrpath
03:06:16     INFO -  JavaScript error: jar:file:///Z:/task_1524279791/build/application/firefox/omni.ja!/components/nsUrlClassifierListManager.js, line 65: NS_ERROR_XPC_GS_RETURNED_FAILURE: Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]
03:06:16     INFO -  JavaScript error: jar:file:///Z:/task_1524279791/build/application/firefox/omni.ja!/components/nsUrlClassifierListManager.js, line 65: NS_ERROR_XPC_GS_RETURNED_FAILURE: Component returned failure code: 0x80570016 (NS_ERROR_XPC_GS_RETURNED_FAILURE) [nsIJSCID.getService]
03:06:16     INFO -  1524279976720	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49850
03:06:16     INFO -  1524279976722	Marionette	DEBUG	Closed connection 0
03:06:16     INFO -  1524279976723	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:49851
03:06:16     INFO -  1524279976724	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
03:06:16     INFO -  1524279976752	Marionette	DEBUG	Register listener.js for window 2147483649
03:06:16     INFO -  1524279976760	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"17e8b69e-08ba-4475-b343-f7c80a686a42","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... 4279791\\AppData\\Local\\Temp\\tmpw3dsh4.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
03:06:16     INFO -  1524279976771	Marionette	TRACE	1 -> [0,2,"Marionette:GetContext",{}]
03:06:16     INFO -  1524279976771	Marionette	TRACE	1 <- [1,2,null,{"value":"content"}]
03:06:16     INFO -  1524279976773	Marionette	TRACE	1 -> [0,3,"Marionette:SetContext",{"value":"chrome"}]
03:06:16     INFO -  1524279976773	Marionette	TRACE	1 <- [1,3,null,{}]
03:06:16     INFO -  1524279976776	Marionette	TRACE	1 -> [0,4,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"Z:\\task_1524279791\\build\\test ... resource://gre/modules/Services.jsm\");\n\n              return Services.appinfo.inSafeMode;","sandbox":"default","line":36}]
03:06:16     INFO -  1524279976777	Marionette	TRACE	1 <- [1,4,null,{"value":true}]
03:06:16     INFO -  1524279976779	Marionette	TRACE	1 -> [0,5,"Marionette:SetContext",{"value":"content"}]
03:06:16     INFO -  1524279976779	Marionette	TRACE	1 <- [1,5,null,{}]
03:06:16     INFO -  1524279976781	Marionette	TRACE	1 -> [0,6,"WebDriver:DeleteSession",{}]
03:06:16     INFO -  1524279976782	Marionette	TRACE	1 <- [1,6,null,{}]
03:06:16     INFO -  Application command: Z:\task_1524279791\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1524279791\appdata\local\temp\tmpsqobs3.mozrunner
03:06:17     INFO -  1524279977380	Marionette	DEBUG	Received observer notification profile-after-change
03:08:17    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_cli_arguments.py TestCommandLineArguments.test_start_in_safe_mode | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
03:08:17     INFO -  Traceback (most recent call last):
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 190, in run
03:08:17     INFO -      self.tearDown()
03:08:17     INFO -    File "Z:\task_1524279791\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_cli_arguments.py", line 23, in tearDown
03:08:17     INFO -      super(TestCommandLineArguments, self).tearDown()
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 338, in tearDown
03:08:17     INFO -      self.marionette.start_session()
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
03:08:17     INFO -      return func(*args, **kwargs)
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1211, in start_session
03:08:17     INFO -      self.start_binary(timeout)
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_driver\marionette.py", line 640, in start_binary
03:08:17     INFO -      reraise(IOError, msg.format(timeout), tb)
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_driver\marionette.py", line 631, in start_binary
03:08:17     INFO -      self.raise_for_port(timeout=timeout)
03:08:17     INFO -    File "Z:\task_1524279791\build\venv\lib\site-packages\marionette_driver\marionette.py", line 711, in raise_for_port
03:08:17     INFO -      self.host, self.port))
03:08:17     INFO -  TEST-INFO took 122382ms

Comment 11

[Intermittent Failures Robot]

1 failures in 782 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1411189&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 12

[Firefox Bug Husbandry Bot]

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

Comment 13

[Intermittent Failures Robot]

1 failures in 655 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1411189&startday=2018-05-28&endday=2018-06-03&tree=trunk

Comment 14

[Firefox Bug Husbandry Bot]

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

Comment 15

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.