Closed Bug 1469946 Opened 6 years ago Closed 6 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback | IOError: Process killed because the connection to Marionette server is lost.

Categories

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

Version 3
defect

Tracking

(Not tracked)

RESOLVED FIXED
mozilla64

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure)

Filed by: nerli [at] mozilla.com

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

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

[task 2018-06-20T15:08:38.320Z] 15:08:38     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback
[task 2018-06-20T15:08:38.337Z] 15:08:38     INFO -  1529507318327	Marionette	DEBUG	Closed connection 1
[task 2018-06-20T15:08:38.337Z] 15:08:38     INFO -  1529507318331	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:47060
[task 2018-06-20T15:08:38.354Z] 15:08:38     INFO -  1529507318343	Marionette	TRACE	2 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-06-20T15:08:38.372Z] 15:08:38     INFO -  1529507318361	Marionette	DEBUG	[2147483649] Frame script loaded
[task 2018-06-20T15:08:38.372Z] 15:08:38     INFO -  1529507318370	Marionette	DEBUG	[2147483649] Frame script registered
[task 2018-06-20T15:08:38.389Z] 15:08:38     INFO -  1529507318379	Marionette	TRACE	2 <- [1,1,null,{"sessionId":"21ced275-fa85-430a-b7c6-87d1a368f02b","capabilities":{"browserName":"firefox","browserVersion":"62.0a ... ssID":5473,"moz:profile":"/tmp/tmpwWgAGO.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-06-20T15:08:38.396Z] 15:08:38     INFO -  1529507318391	Marionette	TRACE	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-06-20T15:08:38.401Z] 15:08:38     INFO -  1529507318397	Marionette	TRACE	2 <- [1,2,null,{"value":null}]
[task 2018-06-20T15:08:38.409Z] 15:08:38     INFO -  1529507318403	Marionette	TRACE	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-06-20T15:08:38.410Z] 15:08:38     INFO -  1529507318406	Marionette	TRACE	2 <- [1,3,null,{"value":null}]
[task 2018-06-20T15:08:38.426Z] 15:08:38     INFO -  1529507318424	Marionette	TRACE	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-06-20T15:08:38.433Z] 15:08:38     INFO -  1529507318430	Marionette	TRACE	2 <- [1,4,null,{"value":null}]
[task 2018-06-20T15:08:38.441Z] 15:08:38     INFO -  1529507318436	Marionette	TRACE	2 -> [0,5,"Marionette:GetContext",{}]
[task 2018-06-20T15:08:38.442Z] 15:08:38     INFO -  1529507318438	Marionette	TRACE	2 <- [1,5,null,{"value":"content"}]
[task 2018-06-20T15:08:38.444Z] 15:08:38     INFO -  1529507318440	Marionette	TRACE	2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-06-20T15:08:38.447Z] 15:08:38     INFO -  1529507318444	Marionette	TRACE	2 <- [1,6,null,{"value":null}]
[task 2018-06-20T15:08:38.452Z] 15:08:38     INFO -  1529507318448	Marionette	TRACE	2 -> [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":878}]
[task 2018-06-20T15:08:38.468Z] 15:08:38     INFO -  1529507318462	Marionette	TRACE	2 <- [1,7,null,{"value":""}]
[task 2018-06-20T15:08:38.468Z] 15:08:38     INFO -  1529507318466	Marionette	TRACE	2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2018-06-20T15:08:38.470Z] 15:08:38     INFO -  1529507318467	Marionette	TRACE	2 <- [1,8,null,{"value":null}]
[task 2018-06-20T15:08:38.474Z] 15:08:38     INFO -  1529507318471	Marionette	TRACE	2 -> [0,9,"Marionette:GetContext",{}]
[task 2018-06-20T15:08:38.474Z] 15:08:38     INFO -  1529507318472	Marionette	TRACE	2 <- [1,9,null,{"value":"content"}]
[task 2018-06-20T15:08:38.479Z] 15:08:38     INFO -  1529507318475	Marionette	TRACE	2 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-06-20T15:08:38.480Z] 15:08:38     INFO -  1529507318477	Marionette	TRACE	2 <- [1,10,null,{"value":null}]
[task 2018-06-20T15:08:38.488Z] 15:08:38     INFO -  1529507318483	Marionette	TRACE	2 -> [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}]
[task 2018-06-20T15:08:38.497Z] 15:08:38     INFO -  1529507318492	Marionette	TRACE	2 <- [1,11,null,{"value":null}]
[task 2018-06-20T15:08:38.498Z] 15:08:38     INFO -  1529507318494	Marionette	TRACE	2 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2018-06-20T15:08:38.500Z] 15:08:38     INFO -  1529507318495	Marionette	TRACE	2 <- [1,12,null,{"value":null}]
[task 2018-06-20T15:08:38.505Z] 15:08:38     INFO -  1529507318500	Marionette	TRACE	2 -> [0,13,"Marionette:GetContext",{}]
[task 2018-06-20T15:08:38.508Z] 15:08:38     INFO -  1529507318502	Marionette	TRACE	2 <- [1,13,null,{"value":"content"}]
[task 2018-06-20T15:08:38.511Z] 15:08:38     INFO -  1529507318504	Marionette	TRACE	2 -> [0,14,"Marionette:AcceptConnections",{"value":false}]
[task 2018-06-20T15:08:38.513Z] 15:08:38     INFO -  1529507318506	Marionette	INFO	Stopped listening on port 2828
[task 2018-06-20T15:08:38.514Z] 15:08:38     INFO -  1529507318506	Marionette	TRACE	2 <- [1,14,null,{"value":null}]
[task 2018-06-20T15:08:38.518Z] 15:08:38     INFO -  1529507318513	Marionette	TRACE	2 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-06-20T15:08:38.519Z] 15:08:38     INFO -  1529507318516	Marionette	TRACE	2 <- [1,15,null,{"value":null}]
[task 2018-06-20T15:08:38.525Z] 15:08:38     INFO -  1529507318522	Marionette	TRACE	2 -> [0,16,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[true],"filename":"tests/testing/marionette/ha ... ags |= Ci.nsIAppStartup.eRestart;\n            }\n            Services.startup.quit(flags);","sandbox":"default","line":119}]
[task 2018-06-20T15:08:38.630Z] 15:08:38     INFO -  1529507318626	Marionette	TRACE	2 <- [1,16,null,{"value":null}]
[task 2018-06-20T15:08:38.733Z] 15:08:38     INFO -  1529507318727	Marionette	DEBUG	Closed connection 2
[task 2018-06-20T15:08:38.836Z] 15:08:38     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-06-20T15:08:39.402Z] 15:08:39     INFO -  1529507319398	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-06-20T15:08:39.403Z] 15:08:39     INFO -  1529507319399	Marionette	DEBUG	Remote service is inactive
[task 2018-06-20T15:08:39.443Z] 15:08:39     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-06-20T15:08:40.091Z] 15:08:40     INFO -  *** You are running in headless mode.
[task 2018-06-20T15:14:39.840Z] 15:14:39     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 111] Connection refused)
This is a hang during Firefox startup.
Depends on: 1433873
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Recent failure log:

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

[task 2018-08-21T05:22:19.003Z] 05:22:19     INFO -  1534828938999	Marionette	TRACE	2 <- [1,16,null,{"value":null}]
[task 2018-08-21T05:22:19.092Z] 05:22:19     INFO -  1534828939088	Marionette	DEBUG	Closed connection 2
[task 2018-08-21T05:22:19.152Z] 05:22:19     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2018-08-21T05:22:19.736Z] 05:22:19     INFO -  1534828939734	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-08-21T05:22:19.739Z] 05:22:19     INFO -  1534828939734	Marionette	DEBUG	Remote service is inactive
[task 2018-08-21T05:28:20.181Z] 05:28:20     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart_with_callback | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 111] Connection refused)
[task 2018-08-21T05:28:20.182Z] 05:28:20     INFO - Traceback (most recent call last):
[task 2018-08-21T05:28:20.182Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-08-21T05:28:20.183Z] 05:28:20     INFO -     testMethod()
[task 2018-08-21T05:28:20.183Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 186, in test_in_app_restart_with_callback
[task 2018-08-21T05:28:20.184Z] 05:28:20     INFO -     callback=lambda: self.shutdown(restart=True))
[task 2018-08-21T05:28:20.184Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-08-21T05:28:20.185Z] 05:28:20     INFO -     return func(*args, **kwargs)
[task 2018-08-21T05:28:20.185Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1180, in restart
[task 2018-08-21T05:28:20.186Z] 05:28:20     INFO -     self.start_session()
[task 2018-08-21T05:28:20.187Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 31, in _
[task 2018-08-21T05:28:20.187Z] 05:28:20     INFO -     m._handle_socket_failure()
[task 2018-08-21T05:28:20.187Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 836, in _handle_socket_failure
[task 2018-08-21T05:28:20.188Z] 05:28:20     INFO -     reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2018-08-21T05:28:20.188Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-08-21T05:28:20.189Z] 05:28:20     INFO -     return func(*args, **kwargs)
[task 2018-08-21T05:28:20.190Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1233, in start_session
[task 2018-08-21T05:28:20.190Z] 05:28:20     INFO -     self.protocol, _ = self.client.connect()
[task 2018-08-21T05:28:20.191Z] 05:28:20     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 195, in connect
[task 2018-08-21T05:28:20.191Z] 05:28:20     INFO -     self._sock.connect((self.host, self.port))
[task 2018-08-21T05:28:20.191Z] 05:28:20     INFO -   File "/usr/lib/python2.7/socket.py", line 228, in meth
[task 2018-08-21T05:28:20.192Z] 05:28:20     INFO -     return getattr(self._sock,name)(*args)
[task 2018-08-21T05:28:20.193Z] 05:28:20     INFO - TEST-INFO took 361843ms
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
No more failures on trunk, so I would say this has been fixed by the patch on bug 1433873.
Assignee: nobody → hskupin
Status: REOPENED → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
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.