1405736 - Intermittent test_profile_management.py TestProfileManagement.test_preferences_are_set | 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: archaeopteryx [at] coole-files.de

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

https://queue.taskcluster.net/v1/task/ZwZ9PM-7RBelaBq85WUj_g/runs/0/artifacts/public/logs/live_backing.log

15:19:58     INFO -  1507130398002	Marionette	TRACE	2 -> [0,8,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"marionette.py","script":"\n                let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n                                              .getService(Components.interfaces.nsIPrefBranch);\n                let pref = 'marionette.test.int';\n                let value = '3';\n                let type = prefInterface.getPrefType(pref);\n                switch(type) {\n                    case prefInterface.PREF_STRING:\n                        return value == prefInterface.getCharPref(pref).toString();\n                    case prefInterface.PREF_BOOL:\n                        return value == prefInterface.getBoolPref(pref).toString();\n                    case prefInterface.PREF_INT:\n                        return value == prefInterface.getIntPref(pref).toString();\n                    case prefInterface.PREF_INVALID:\n                        return false;\n                }\n                ","sandbox":"default","line":1018}]
15:19:58     INFO -  1507130398004	Marionette	TRACE	2 <- [1,8,null,{"value":false}]
15:19:58     INFO -  1507130398020	Marionette	TRACE	2 -> [0,9,"setContext",{"value":"content"}]
15:19:58     INFO -  1507130398020	Marionette	TRACE	2 <- [1,9,null,{}]
15:19:58     INFO -  1507130398022	Marionette	TRACE	2 -> [0,10,"getContext",{}]
15:19:58     INFO -  1507130398022	Marionette	TRACE	2 <- [1,10,null,{"value":"content"}]
15:19:58     INFO -  1507130398032	Marionette	TRACE	2 -> [0,11,"deleteSession",{}]
15:19:58     INFO -  1507130398034	Marionette	TRACE	2 <- [1,11,null,{}]
15:19:58     INFO -  Application command: Z:\task_1507129295\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmphn3q8t.mozrunner
15:19:58     INFO -  1507130398536	Marionette	DEBUG	Received observer notification "profile-after-change"
15:23:59    ERROR -  TEST-UNEXPECTED-ERROR | test_profile_management.py TestProfileManagement.test_preferences_are_set | 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!)
15:23:59     INFO -  Traceback (most recent call last):
15:23:59     INFO -    File "Z:\task_1507129295\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 137, in run
15:23:59     INFO -      self.setUp()
15:23:59     INFO -    File "Z:\task_1507129295\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 15, in setUp
15:23:59     INFO -      "marionette.test.int": 3
15:23:59     INFO -    File "Z:\task_1507129295\build\venv\lib\site-packages\marionette_driver\decorators.py", line 28, in _
15:23:59     INFO -      m._handle_socket_failure()
15:23:59     INFO -    File "Z:\task_1507129295\build\venv\lib\site-packages\marionette_driver\decorators.py", line 23, in _
15:23:59     INFO -      return func(*args, **kwargs)
15:23:59     INFO -    File "Z:\task_1507129295\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1026, in enforce_gecko_prefs
15:23:59     INFO -      self.raise_for_port()
15:23:59     INFO -    File "Z:\task_1507129295\build\venv\lib\site-packages\marionette_driver\marionette.py", line 722, in raise_for_port
15:23:59     INFO -      self.host, self.port))
15:23:59     INFO -  TEST-INFO took 241508ms

Comment 1

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

There is no `sessionstore-windows-restored` observer notification received.

Comment 2

[Intermittent Failures Robot]

1 failures in 824 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=1405736&startday=2017-10-02&endday=2017-10-08&tree=all

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:
* autoland: 1

Platform breakdown:
* windows10-64: 1

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

Comment 4

[Intermittent Failures Robot]

1 failures in 762 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=1405736&startday=2017-11-13&endday=2017-11-19&tree=all

Comment 5

[Firefox Bug Husbandry Bot]

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

Comment 6

[Andreea Pavel [:apavel]]

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

11:18:46     INFO -  TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name
11:18:46     INFO -  1516965526316	Marionette	DEBUG	Closed connection 3
11:18:46     INFO -  1516965526318	Marionette	DEBUG	Accepted connection 4 from 127.0.0.1:51982
11:18:46     INFO -  1516965526321	Marionette	TRACE	4 -> [0,1,"newSession",{}]
11:18:46     INFO -  1516965526323	Marionette	DEBUG	Register listener.js for window 4294967297
11:18:46     INFO -  1516965526327	Marionette	TRACE	4 <- [1,1,null,{"sessionId":"3e8c885a-6116-4a3f-bfec-4e37ea63c5a6","capabilities":{"browserName":"firefox","browserVersion":"60.0a ... processID":7068,"moz:profile":"C:\\Users\\GenericWorker\\AppData\\Local\\Temp\\tmppzsnx9.foobar","moz:webdriverClick":true}}]
11:18:46     INFO -  1516965526330	Marionette	TRACE	4 -> [0,2,"setTimeouts",{"script":30000}]
11:18:46     INFO -  1516965526331	Marionette	TRACE	4 <- [1,2,null,{}]
11:18:46     INFO -  1516965526336	Marionette	TRACE	4 -> [0,3,"setTimeouts",{"pageLoad":300000}]
11:18:46     INFO -  1516965526337	Marionette	TRACE	4 <- [1,3,null,{}]
11:18:46     INFO -  1516965526342	Marionette	TRACE	4 -> [0,4,"setTimeouts",{"implicit":0}]
11:18:46     INFO -  1516965526343	Marionette	TRACE	4 <- [1,4,null,{}]
11:18:46     INFO -  1516965526348	Marionette	TRACE	4 -> [0,5,"deleteSession",{}]
11:18:46     INFO -  1516965526349	Marionette	TRACE	4 <- [1,5,null,{}]
11:18:46     INFO -  Application command: Z:\task_1516965056\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmp1vqpkm.mozrunner
11:18:46     INFO -  1516965526920	Marionette	DEBUG	Received observer notification profile-after-change
11:20:46    ERROR -  TEST-UNEXPECTED-ERROR | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithoutWorkspace.test_new_random_profile_name | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
11:20:46     INFO -  Traceback (most recent call last):
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
11:20:46     INFO -      testMethod()
11:20:46     INFO -    File "Z:\task_1516965056\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 162, in test_new_random_profile_name
11:20:46     INFO -      self.marionette.start_session()
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
11:20:46     INFO -      return func(*args, **kwargs)
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1211, in start_session
11:20:46     INFO -      self.start_binary(timeout)
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_driver\marionette.py", line 645, in start_binary
11:20:46     INFO -      reraise(IOError, msg.format(timeout), tb)
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_driver\marionette.py", line 636, in start_binary
11:20:46     INFO -      self.raise_for_port(timeout=timeout)
11:20:46     INFO -    File "Z:\task_1516965056\build\venv\lib\site-packages\marionette_driver\marionette.py", line 716, in raise_for_port
11:20:46     INFO -      self.host, self.port))
11:20:46     INFO -  TEST-INFO took 120395ms
11:20:46     INFO -  Application command: Z:\task_1516965056\build\application\firefox\firefox.exe -no-remote -marionette -profile c:\users\genericworker\appdata\local\temp\tmptozirf.mozrunner
11:20:47     INFO -  1516965647183	Marionette	DEBUG	Received observer notification profile-after-change
11:20:47     INFO -  1516965647269	Marionette	DEBUG	Received observer notification command-line-startup
11:20:47     INFO -  1516965647269	Marionette	DEBUG	Enabled via flag
11:20:47     INFO -  [DEBUG SHUTDOWN] Register: decoder=000002190C59D000, count=1
11:20:47     INFO -  [DEBUG SHUTDOWN] ShutdownDecoder: decoder: 'wmf software video decoder - yuv420' (000002190966A6A0) flush:1
11:20:47     INFO -  [DEBUG SHUTDOWN] operator (): pool=00000219049D50D0 shutdown=false count=0
11:20:48     INFO -  1516965648507	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
11:20:48     INFO -  1516965648817	Marionette	DEBUG	New connections are accepted
11:20:48     INFO -  1516965648818	Marionette	INFO	Listening on port 2828
11:20:48     INFO -  1516965648923	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:52198
11:20:49     INFO -  1516965649025	Marionette	DEBUG	Closed connection 0
11:20:49     INFO -  1516965649025	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:52205
11:20:49     INFO -  1516965649123	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:52208
11:20:49     INFO -  1516965649125	Marionette	DEBUG	Closed connection 2
11:20:49     INFO -  1516965649126	Marionette	DEBUG	Closed connection 1
11:20:49     INFO -  1516965649127	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:52209
11:20:49     INFO -  1516965649130	Marionette	TRACE	3 -> [0,1,"newSession",{}]
11:20:49     INFO -  1516965649196	Marionette	DEBUG	Register listener.js for window 4294967297
11:20:49     INFO -  1516965649203	Marionette	TRACE	3 <- [1,1,null,{"sessionId":"ade5b306-3f59-4090-8b37-10aacc2a5271","capabilities":{"browserName":"firefox","browserVersion":"60.0a ... cessID":7768,"moz:profile":"C:\\Users\\GenericWorker\\AppData\\Local\\Temp\\tmptozirf.mozrunner","moz:webdriverClick":true}}]
11:20:49     INFO -  1516965649209	Marionette	TRACE	3 -> [0,2,"deleteSession",{}]
11:20:49     INFO -  1516965649211	Marionette	TRACE	3 <- [1,2,null,{}]

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1
* autoland: 1

Platform breakdown:
* windows10-64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1405736&startday=2018-01-22&endday=2018-01-28&tree=all

Comment 8

[Firefox Bug Husbandry Bot]

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

Comment 9

[BMO Automation]

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