1489401 - Intermittent /harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 111] Connection refused)

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: rgurzau [at] mozilla.com

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

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

[task 2018-09-07T04:32:42.555Z] 04:32:42     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart
[task 2018-09-07T04:32:42.572Z] 04:32:42     INFO -  1536294762562	Marionette	DEBUG	Closed connection 1
[task 2018-09-07T04:32:42.572Z] 04:32:42     INFO -  1536294762565	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:50514
[task 2018-09-07T04:32:42.573Z] 04:32:42     INFO -  1536294762569	Marionette	TRACE	2 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-09-07T04:32:42.581Z] 04:32:42     INFO -  1536294762578	Marionette	DEBUG	[2147483649] Frame script loaded
[task 2018-09-07T04:32:42.589Z] 04:32:42     INFO -  1536294762583	Marionette	DEBUG	[2147483649] Frame script registered
[task 2018-09-07T04:32:42.597Z] 04:32:42     INFO -  1536294762591	Marionette	TRACE	2 <- [1,1,null,{"sessionId":"e7320c64-44b2-47c2-b27d-74968686a873","capabilities":{"browserName":"firefox","browserVersion":"64.0a ... ssID":6531,"moz:profile":"/tmp/tmpVW301b.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-09-07T04:32:42.605Z] 04:32:42     INFO -  1536294762601	Marionette	TRACE	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-09-07T04:32:42.613Z] 04:32:42     INFO -  1536294762607	Marionette	TRACE	2 <- [1,2,null,{"value":null}]
[task 2018-09-07T04:32:42.621Z] 04:32:42     INFO -  1536294762615	Marionette	TRACE	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-09-07T04:32:42.621Z] 04:32:42     INFO -  1536294762617	Marionette	TRACE	2 <- [1,3,null,{"value":null}]
[task 2018-09-07T04:32:42.638Z] 04:32:42     INFO -  1536294762628	Marionette	TRACE	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-09-07T04:32:42.639Z] 04:32:42     INFO -  1536294762632	Marionette	TRACE	2 <- [1,4,null,{"value":null}]
[task 2018-09-07T04:32:42.654Z] 04:32:42     INFO -  1536294762651	Marionette	TRACE	2 -> [0,5,"Marionette:GetContext",{}]
[task 2018-09-07T04:32:42.662Z] 04:32:42     INFO -  1536294762660	Marionette	TRACE	2 <- [1,5,null,{"value":"content"}]
[task 2018-09-07T04:32:42.671Z] 04:32:42     INFO -  1536294762665	Marionette	TRACE	2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-09-07T04:32:42.671Z] 04:32:42     INFO -  1536294762667	Marionette	TRACE	2 <- [1,6,null,{"value":null}]
[task 2018-09-07T04:32:42.788Z] 04:32:42     INFO -  1536294762780	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":893}]
[task 2018-09-07T04:32:42.807Z] 04:32:42     INFO -  1536294762792	Marionette	TRACE	2 <- [1,7,null,{"value":""}]
[task 2018-09-07T04:32:42.864Z] 04:32:42     INFO -  1536294762854	Marionette	TRACE	2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2018-09-07T04:32:42.864Z] 04:32:42     INFO -  1536294762855	Marionette	TRACE	2 <- [1,8,null,{"value":null}]
[task 2018-09-07T04:32:42.946Z] 04:32:42     INFO -  1536294762930	Marionette	TRACE	2 -> [0,9,"Marionette:GetContext",{}]
[task 2018-09-07T04:32:42.946Z] 04:32:42     INFO -  1536294762931	Marionette	TRACE	2 <- [1,9,null,{"value":"content"}]
[task 2018-09-07T04:32:42.947Z] 04:32:42     INFO -  1536294762940	Marionette	TRACE	2 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-09-07T04:32:42.947Z] 04:32:42     INFO -  1536294762941	Marionette	TRACE	2 <- [1,10,null,{"value":null}]
[task 2018-09-07T04:32:42.982Z] 04:32:42     INFO -  1536294762975	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":927}]
[task 2018-09-07T04:32:42.998Z] 04:32:42     INFO -  1536294762985	Marionette	TRACE	2 <- [1,11,null,{"value":null}]
[task 2018-09-07T04:32:43.036Z] 04:32:43     INFO -  1536294763033	Marionette	TRACE	2 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2018-09-07T04:32:43.038Z] 04:32:43     INFO -  1536294763035	Marionette	TRACE	2 <- [1,12,null,{"value":null}]
[task 2018-09-07T04:32:43.048Z] 04:32:43     INFO -  1536294763043	Marionette	TRACE	2 -> [0,13,"Marionette:GetContext",{}]
[task 2018-09-07T04:32:43.050Z] 04:32:43     INFO -  1536294763044	Marionette	TRACE	2 <- [1,13,null,{"value":"content"}]
[task 2018-09-07T04:32:43.052Z] 04:32:43     INFO -  1536294763046	Marionette	TRACE	2 -> [0,14,"Marionette:GetContext",{}]
[task 2018-09-07T04:32:43.054Z] 04:32:43     INFO -  1536294763047	Marionette	TRACE	2 <- [1,14,null,{"value":"content"}]
[task 2018-09-07T04:32:43.063Z] 04:32:43     INFO -  1536294763057	Marionette	TRACE	2 -> [0,15,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-09-07T04:32:43.065Z] 04:32:43     INFO -  1536294763058	Marionette	TRACE	2 <- [1,15,null,{"value":null}]
[task 2018-09-07T04:32:43.071Z] 04:32:43     INFO -  1536294763064	Marionette	TRACE	2 -> [0,16,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"../../venv/lib/python2.7/site-p ... ancelQuit, \"quit-application-requested\", null);\n                return cancelQuit.data;","sandbox":"default","line":1062}]
[task 2018-09-07T04:32:43.088Z] 04:32:43     INFO -  1536294763080	Marionette	TRACE	2 <- [1,16,null,{"value":false}]
[task 2018-09-07T04:32:43.090Z] 04:32:43     INFO -  1536294763083	Marionette	TRACE	2 -> [0,17,"Marionette:SetContext",{"value":"content"}]
[task 2018-09-07T04:32:43.092Z] 04:32:43     INFO -  1536294763084	Marionette	TRACE	2 <- [1,17,null,{"value":null}]
[task 2018-09-07T04:32:43.110Z] 04:32:43     INFO -  1536294763095	Marionette	TRACE	2 -> [0,18,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
[task 2018-09-07T04:32:43.112Z] 04:32:43     INFO -  1536294763097	Marionette	INFO	Stopped listening on port 2828
[task 2018-09-07T04:32:43.263Z] 04:32:43     INFO -  1536294763259	Marionette	TRACE	2 <- [1,18,null,{"cause":"restart"}]
[task 2018-09-07T04:32:43.349Z] 04:32:43     INFO -  1536294763345	Marionette	DEBUG	Closed connection 2
[task 2018-09-07T04:32:43.370Z] 04:32:43     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x300105,name=PContent::Msg_AccumulateChildHistograms) Closed channel: cannot send/recv
[task 2018-09-07T04:32:43.372Z] 04:32:43     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x300106,name=PContent::Msg_AccumulateChildKeyedHistograms) Closed channel: cannot send/recv
[task 2018-09-07T04:32:43.374Z] 04:32:43     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x30010A,name=PContent::Msg_RecordDiscardedData) Closed channel: cannot send/recv
[task 2018-09-07T04:32:43.993Z] 04:32:43     INFO -  1536294763989	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-09-07T04:32:43.996Z] 04:32:43     INFO -  1536294763989	Marionette	DEBUG	Remote service is inactive
[task 2018-09-07T04:38:44.430Z] 04:38:44     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py TestQuitRestart.test_in_app_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: [Errno 111] Connection refused)
[task 2018-09-07T04:38:44.432Z] 04:38:44     INFO - Traceback (most recent call last):
[task 2018-09-07T04:38:44.433Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-09-07T04:38:44.433Z] 04:38:44     INFO -     testMethod()
[task 2018-09-07T04:38:44.434Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_quit_restart.py", line 171, in test_in_app_restart
[task 2018-09-07T04:38:44.435Z] 04:38:44     INFO -     self.marionette.restart(in_app=True)
[task 2018-09-07T04:38:44.436Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-09-07T04:38:44.437Z] 04:38:44     INFO -     return func(*args, **kwargs)
[task 2018-09-07T04:38:44.439Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1183, in restart
[task 2018-09-07T04:38:44.440Z] 04:38:44     INFO -     self.start_session()
[task 2018-09-07T04:38:44.442Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 31, in _
[task 2018-09-07T04:38:44.443Z] 04:38:44     INFO -     m._handle_socket_failure()
[task 2018-09-07T04:38:44.444Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 839, in _handle_socket_failure
[task 2018-09-07T04:38:44.446Z] 04:38:44     INFO -     reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2018-09-07T04:38:44.447Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2018-09-07T04:38:44.449Z] 04:38:44     INFO -     return func(*args, **kwargs)
[task 2018-09-07T04:38:44.450Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1236, in start_session
[task 2018-09-07T04:38:44.451Z] 04:38:44     INFO -     self.protocol, _ = self.client.connect()
[task 2018-09-07T04:38:44.452Z] 04:38:44     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 195, in connect
[task 2018-09-07T04:38:44.454Z] 04:38:44     INFO -     self._sock.connect((self.host, self.port))
[task 2018-09-07T04:38:44.455Z] 04:38:44     INFO -   File "/usr/lib/python2.7/socket.py", line 228, in meth
[task 2018-09-07T04:38:44.457Z] 04:38:44     INFO -     return getattr(self._sock,name)(*args)
[task 2018-09-07T04:38:44.458Z] 04:38:44     INFO - TEST-INFO took 361873ms

Comment 1

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

Looks like a shutdown hang of Firefox.

Comment 2

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1489401&startday=2018-09-03&endday=2018-09-09&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 3
* mozilla-inbound: 2
* mozilla-central: 1

Platform breakdown:
* linux64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1489401&startday=2018-09-10&endday=2018-09-16&tree=all

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1
* mozilla-central: 2

Platform breakdown:
* linux64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1489401&startday=2018-09-17&endday=2018-09-23&tree=all

Comment 5

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1489401&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 6

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1489401&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 7

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

This as actually an ASAN hang only failure, and got fixed by bug 1495404.

Comment 8

[BMO Automation]

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