1402138 - Intermittent test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on localhost:2828!)

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

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

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

Comment 1

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

No further log entries than the `profile-after-change` notification. It simply stopped:

20:53:14     INFO -  Application command: Z:\task_1506026740\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmpv9lmos.mozrunner
20:53:14     INFO -  *** You are running in headless mode.
20:53:14     INFO -  1506027194977	Marionette	DEBUG	Received observer notification "profile-after-change"
20:57:15    ERROR -  TEST-UNEXPECTED-ERROR | test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on localhost:2828!)

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 2

Platform breakdown:
* windows10-64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1402138&startday=2017-09-18&endday=2017-09-24&tree=all

Comment 3

[Emma Humphries ☕️🎸🧞‍♀️✨ (she/they) [:emceeaich] (Pacific Time) use needinfo]

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

Comment 4

[Narcis Beleuzu [:NarcisB]]

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified&selectedJob=139171156

ERROR -  TEST-UNEXPECTED-ERROR | test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on localhost:2828!)

Comment 5

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

Actually this is dependent on bug 1382162.

Comment 6

[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=1402138&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1402138&startday=2017-11-06&endday=2017-11-12&tree=all

Comment 8

[Firefox Bug Husbandry Bot]

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

Comment 9

[Intermittent Failures Robot]

2 failures in 788 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=1402138&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 10

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=171360133&repo=mozilla-inbound&lineNumber=31420

Comment 11

[Intermittent Failures Robot]

1 failures in 792 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=1402138&startday=2018-04-09&endday=2018-04-15&tree=trunk

Comment 12

[Firefox Bug Husbandry Bot]

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

Comment 13

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=184417447&repo=mozilla-inbound&lineNumber=33186

18:49:06     INFO -  1529693346305	Marionette	TRACE	4 <- [1,10,null,{"value":null}]
18:49:06     INFO -  1529693346309	Marionette	TRACE	4 -> [0,11,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url","about:about", ... = new Preferences({defaultBranch: defaultBranch});\n                prefs.set(pref, value);","sandbox":"default","line":912}]
18:49:06     INFO -  1529693346311	Marionette	TRACE	4 <- [1,11,null,{"value":null}]
18:49:06     INFO -  1529693346313	Marionette	TRACE	4 -> [0,12,"Marionette:SetContext",{"value":"content"}]
18:49:06     INFO -  1529693346313	Marionette	TRACE	4 <- [1,12,null,{"value":null}]
18:49:06     INFO -  1529693346316	Marionette	TRACE	4 -> [0,13,"Marionette:GetContext",{}]
18:49:06     INFO -  1529693346316	Marionette	TRACE	4 <- [1,13,null,{"value":"content"}]
18:49:06     INFO -  1529693346319	Marionette	TRACE	4 -> [0,14,"WebDriver:DeleteSession",{}]
18:49:06     INFO -  1529693346320	Marionette	TRACE	4 <- [1,14,null,{"value":null}]
18:49:06     INFO -  1529693346324	Marionette	DEBUG	Closed connection 4
18:49:06     INFO -  Application command: Z:\task_1529691463\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1529691463\appdata\local\temp\tmpfo6wm5.mozrunner
18:49:07     INFO -  1529693347069	Marionette	DEBUG	Received observer notification profile-after-change
18:53:07    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on localhost:2828!)
18:53:07     INFO -  Traceback (most recent call last):
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
18:53:07     INFO -      testMethod()
18:53:07     INFO -    File "Z:\task_1529691463\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py", line 122, in test_force_clean_restart
18:53:07     INFO -      self.marionette.restart(clean=True)
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_driver\decorators.py", line 31, in _
18:53:07     INFO -      m._handle_socket_failure()
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_driver\marionette.py", line 824, in _handle_socket_failure
18:53:07     INFO -      reraise(IOError, message.format(returncode=returncode, reason=val), tb)
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
18:53:07     INFO -      return func(*args, **kwargs)
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1162, in restart
18:53:07     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
18:53:07     INFO -    File "Z:\task_1529691463\build\venv\lib\site-packages\marionette_driver\marionette.py", line 710, in raise_for_port
18:53:07     INFO -      self.host, self.port))
18:53:07     INFO -  TEST-INFO took 241435ms
18:53:07     INFO -  Application command: Z:\task_1529691463\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1529691463\appdata\local\temp\tmpf8mt7o.mozrunner

Comment 14

[Intermittent Failures Robot]

1 failures in 521 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=1402138&startday=2018-06-18&endday=2018-06-24&tree=trunk

Comment 15

[Firefox Bug Husbandry Bot]

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

Comment 16

[Andreea Pavel [:apavel]]

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

10:14:14     INFO -  1533809654804	Marionette	TRACE	4 <- [1,12,null,{"value":null}]
10:14:14     INFO -  1533809654805	Marionette	TRACE	4 -> [0,13,"Marionette:GetContext",{}]
10:14:14     INFO -  1533809654805	Marionette	TRACE	4 <- [1,13,null,{"value":"content"}]
10:14:14     INFO -  1533809654805	Marionette	TRACE	4 -> [0,14,"WebDriver:DeleteSession",{}]
10:14:14     INFO -  1533809654807	Marionette	TRACE	4 <- [1,14,null,{"value":null}]
10:14:14     INFO -  Application command: Z:\task_1533807298\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1533807298\appdata\local\temp\tmpt6dofa.mozrunner
10:14:14     INFO -  *** You are running in headless mode.
10:14:15     INFO -  1533809655306	Marionette	DEBUG	Received observer notification profile-after-change
10:14:15     INFO -  1533809655347	Marionette	DEBUG	Received observer notification toplevel-window-ready
10:14:15     INFO -  1533809655364	Marionette	DEBUG	Received observer notification command-line-startup
10:14:15     INFO -  1533809655364	Marionette	DEBUG	Received observer notification nsPref:changed
10:14:15     INFO -  1533809655364	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
10:18:16    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
10:18:16     INFO -  Traceback (most recent call last):
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
10:18:16     INFO -      testMethod()
10:18:16     INFO -    File "Z:\task_1533807298\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py", line 122, in test_force_clean_restart
10:18:16     INFO -      self.marionette.restart(clean=True)
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_driver\decorators.py", line 31, in _
10:18:16     INFO -      m._handle_socket_failure()
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_driver\marionette.py", line 836, in _handle_socket_failure
10:18:16     INFO -      reraise(IOError, message.format(returncode=returncode, reason=val), tb)
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
10:18:16     INFO -      return func(*args, **kwargs)
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1174, in restart
10:18:16     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
10:18:16     INFO -    File "Z:\task_1533807298\build\venv\lib\site-packages\marionette_driver\marionette.py", line 726, in raise_for_port
10:18:16     INFO -      self.host, self.port))
10:18:16     INFO -  TEST-INFO took 241385ms
10:18:16     INFO -  Application command: Z:\task_1533807298\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\task_1533807298\appdata\local\temp\tmpkwxgse.mozrunner

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1402138&startday=2018-08-06&endday=2018-08-12&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1402138&startday=2018-08-20&endday=2018-08-26&tree=all

Comment 19

[Firefox Bug Husbandry Bot]

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

Comment 20

[Arthur Iakab [arthur_iakab]]

Recently failed here https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&selectedJob=208283551&revision=58e4d71be51834d92aabdca2955d38f476525f71

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

Comment 21

[Intermittent Failures Robot]

1 failures in 2584 pushes (0.0 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=1402138&startday=2018-10-22&endday=2018-10-28&tree=all

Comment 22

[Firefox Bug Husbandry Bot]

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

Comment 23

[Cristina Coroiu [:ccoroiu]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=217355105&repo=mozilla-central&lineNumber=31793

01:34:07     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py TestQuitRestart.test_force_clean_restart
01:34:07     INFO -  1545010447379	Marionette	DEBUG	Accepted connection 4 from 127.0.0.1:51983
01:34:07     INFO -  1545010447380	Marionette	DEBUG	Closed connection 3
01:34:07     INFO -  1545010447382	Marionette	DEBUG	4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
01:34:07     INFO -  1545010447383	Marionette	TRACE	[6442450945] Frame script loaded
01:34:07     INFO -  1545010447384	Marionette	TRACE	[6442450945] Frame script registered
01:34:07     INFO -  1545010447385	Marionette	DEBUG	4 <- [1,1,null,{"sessionId":"901f754d-8aba-456c-af13-b2246ff11511","capabilities":{"browserName":"firefox","browserVersion":"66.0a ... p\\tmpk5fzo8.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
01:34:07     INFO -  1545010447387	Marionette	DEBUG	4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
01:34:07     INFO -  1545010447387	Marionette	DEBUG	4 <- [1,2,null,{"value":null}]
01:34:07     INFO -  1545010447388	Marionette	DEBUG	4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
01:34:07     INFO -  1545010447388	Marionette	DEBUG	4 <- [1,3,null,{"value":null}]
01:34:07     INFO -  1545010447389	Marionette	DEBUG	4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
01:34:07     INFO -  1545010447390	Marionette	DEBUG	4 <- [1,4,null,{"value":null}]
01:34:07     INFO -  1545010447391	Marionette	DEBUG	4 -> [0,5,"Marionette:GetContext",{}]
01:34:07     INFO -  1545010447391	Marionette	DEBUG	4 <- [1,5,null,{"value":"content"}]
01:34:07     INFO -  1545010447392	Marionette	DEBUG	4 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
01:34:07     INFO -  1545010447392	Marionette	DEBUG	4 <- [1,6,null,{"value":null}]
01:34:07     INFO -  1545010447393	Marionette	DEBUG	4 -> [0,7,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url",false,"unspecif ... tBranch});\n                return prefs.get(pref, null, Components.interfaces[valueType]);","sandbox":"default","line":898}]
01:34:07     INFO -  1545010447394	Marionette	DEBUG	4 <- [1,7,null,{"value":"https://www.mozilla.org/projects/firefox/%VERSION%/firstrun/"}]
01:34:07     INFO -  1545010447395	Marionette	DEBUG	4 -> [0,8,"Marionette:SetContext",{"value":"content"}]
01:34:07     INFO -  1545010447396	Marionette	DEBUG	4 <- [1,8,null,{"value":null}]
01:34:07     INFO -  1545010447396	Marionette	DEBUG	4 -> [0,9,"Marionette:GetContext",{}]
01:34:07     INFO -  1545010447396	Marionette	DEBUG	4 <- [1,9,null,{"value":"content"}]
01:34:07     INFO -  1545010447397	Marionette	DEBUG	4 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
01:34:07     INFO -  1545010447397	Marionette	DEBUG	4 <- [1,10,null,{"value":null}]
01:34:07     INFO -  1545010447401	Marionette	DEBUG	4 -> [0,11,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["startup.homepage_welcome_url","about:about", ... = new Preferences({defaultBranch: defaultBranch});\n                prefs.set(pref, value);","sandbox":"default","line":932}]
01:34:07     INFO -  1545010447403	Marionette	DEBUG	4 <- [1,11,null,{"value":null}]
01:34:07     INFO -  1545010447404	Marionette	DEBUG	4 -> [0,12,"Marionette:SetContext",{"value":"content"}]
01:34:07     INFO -  1545010447404	Marionette	DEBUG	4 <- [1,12,null,{"value":null}]
01:34:07     INFO -  1545010447405	Marionette	DEBUG	4 -> [0,13,"Marionette:GetContext",{}]
01:34:07     INFO -  1545010447405	Marionette	DEBUG	4 <- [1,13,null,{"value":"content"}]
01:34:07     INFO -  1545010447406	Marionette	DEBUG	4 -> [0,14,"WebDriver:DeleteSession",{}]
01:34:07     INFO -  1545010447407	Marionette	DEBUG	4 <- [1,14,null,{"value":null}]
01:34:07     INFO -  Application command: Z:\task_1545009895\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile c:\users\task_1545009895\appdata\local\temp\tmptzi4rp.mozrunner
01:34:07     INFO -  *** You are running in headless mode.
01:34:07     INFO -  1545010447827	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid host permission: resource://pdf.js/
01:34:07     INFO -  1545010447828	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid host permission: about:reader*
01:34:07     INFO -  1545010447947	Marionette	TRACE	Received observer notification profile-after-change
01:34:07     INFO -  1545010447983	Marionette	TRACE	Received observer notification toplevel-window-ready
01:34:08     INFO -  1545010448000	Marionette	TRACE	Received observer notification command-line-startup
01:34:08     INFO -  1545010448000	Marionette	TRACE	Received observer notification nsPref:changed
01:34:08     INFO -  1545010448001	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
01:37:18    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py TestQuitRestart.test_force_clean_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
01:37:18     INFO -  Traceback (most recent call last):
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
01:37:18     INFO -      testMethod()
01:37:18     INFO -    File "Z:\task_1545009895\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_quit_restart.py", line 131, in test_force_clean_restart
01:37:18     INFO -      self.marionette.restart(clean=True)
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
01:37:18     INFO -      m._handle_socket_failure()
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_driver\marionette.py", line 844, in _handle_socket_failure
01:37:18     INFO -      reraise(IOError, message.format(returncode=returncode, reason=val), tb)
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
01:37:18     INFO -      return func(*args, **kwargs)
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1218, in restart
01:37:18     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
01:37:18     INFO -    File "Z:\task_1545009895\build\venv\lib\site-packages\marionette_driver\marionette.py", line 735, in raise_for_port
01:37:18     INFO -      self.host, self.port))
01:37:18     INFO -  TEST-INFO took 191403ms

Comment 24

[Intermittent Failures Robot]

1 failures in 2648 pushes (0.0 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://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1402138&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 25

[Firefox Bug Husbandry Bot]

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

Comment 26

[BMO Automation]

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