1374077 - Intermittent mochitest Automation Error: Received unexpected exception while running application after error: [Errno 61] Connection refused

Status: RESOLVED FIXED

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

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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

06:02:08     INFO - Application command: /Users/cltbld/tasks/task_1497789281/build/application/Nightly.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/g0/y19jzr9d3sddq_fp6fk93t4h00000w/T/tmpBqlL_V.mozrunner
06:02:08     INFO - runtests.py | Application pid: 1960
06:02:08     INFO - TEST-INFO | started process GECKO(1960)
06:04:08     INFO -  Traceback (most recent call last):
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/tests/mochitest/runtests.py", line 2515, in doTests
06:04:08     INFO -      marionette_args=marionette_args,
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/tests/mochitest/runtests.py", line 2112, in runApp
06:04:08     INFO -      self.marionette.start_session(timeout=port_timeout)
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 28, in _
06:04:08     INFO -      m._handle_socket_failure()
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 23, in _
06:04:08     INFO -      return func(*args, **kwargs)
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1210, in start_session
06:04:08     INFO -      self.protocol, _ = self.client.connect()
06:04:08     INFO -    File "/Users/cltbld/tasks/task_1497789281/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 223, in connect
06:04:08     INFO -      self.sock.connect((self.addr, self.port))
06:04:08     INFO -    File "/tools/python27/lib/python2.7/socket.py", line 224, in meth
06:04:08     INFO -      return getattr(self._sock,name)(*args)
06:04:08     INFO -  error: [Errno 61] Connection refused
06:04:08    ERROR - Automation Error: Received unexpected exception while running application

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Looks like it only hits OSX. wcosta, regression from bug 1372229?

Comment 2

[Intermittent Failures Robot]

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

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

Platform breakdown:
* osx-10-10: 3
* linux64: 1

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

Comment 3

[Wander Lairson Costa]

I feel this is a some sort of race condition that is only spotted in taskcluster.
Reading the code, it makes sure there is a listening Marionette port before moving on.
My guess is that Marionette server accepts only one connection at a time, and somehow connect is being called before close syscall completes (not sure how).

:maja, any idea what could be going on?

Comment 4

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

Answering for Maja given that she is not around right now...

By default Marionette server (in Firefox) is only listening on port 2828, so if this port is already in use a connection attempt will fail. I could imagine that this is happening here. Also because for the part of the log where this issue occurs there is no such line:

> Marionette	INFO	Listening on port 2828

Comment 5

[Intermittent Failures Robot]

5 failures in 892 pushes (0.006 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* try: 4
* autoland: 1

Platform breakdown:
* osx-10-10: 5

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-cross: 1

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

Comment 7

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

Marionette got enabled and setup it's server socket. But something didn't allow the connection:

13:05:51     INFO - GECKO(1681) | 1499544351984	Marionette	INFO	Enabled via --marionette
13:05:53     INFO - GECKO(1681) | 1499544353568	Marionette	INFO	Listening on port 2828
13:05:53     INFO - GECKO(1681) | 2017-07-08 13:05:53.609 plugin-container[1684:10914] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9737, name = 'com.apple.tsm.portname'
13:05:53     INFO - GECKO(1681) | See /usr/include/servers/bootstrap_defs.h for the error codes.
13:05:53     INFO - GECKO(1681) | 2017-07-08 13:05:53.612 plugin-container[1684:10914] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x4713, name = 'com.apple.CFPasteboardClient'
13:05:53     INFO - GECKO(1681) | See /usr/include/servers/bootstrap_defs.h for the error codes.
13:05:53     INFO - GECKO(1681) | 2017-07-08 13:05:53.612 plugin-container[1684:10914] Failed to allocate communication port for com.apple.CFPasteboardClient; this is likely due to sandbox restrictions
13:05:53     INFO - GECKO(1681) | [Child 1684] WARNING: pipe error: Broken pipe: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 709
13:05:53     INFO - GECKO(1681) | ** Unknown exception behavior: -2147483647
1

Maybe the broken pipe caused a hang?

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1
* mozilla-beta: 1
* autoland: 1

Platform breakdown:
* osx-10-10: 3

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

Comment 11

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 1
* linux32-stylo: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1374077&startday=2017-08-21&endday=2017-08-27&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

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

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 2

Platform breakdown:
* linux64: 2

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

Comment 14

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

We only waited 60s for startup of Firefox. So my patches for bug 1399592 and bug 1400786 should fix that failure.

Comment 15

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

I would claim that this is fixed now with both dependent patches seeing landed.

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-esr52: 2

Platform breakdown:
* linux64: 2

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

Comment 17

[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-esr52: 1

Platform breakdown:
* windows8-64: 1

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

Comment 18

[BMO Automation]

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