Closed Bug 1374077 Opened 7 years ago Closed 7 years ago

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

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Platform:
Unspecified
macOS
Type:
defect

Tracking

(firefox57 fixed)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox57 --- fixed

People

(Reporter: aryx, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure) 

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
Looks like it only hits OSX. wcosta, regression from bug 1372229?
Flags: needinfo?(wcosta)
OS: Unspecified → Mac OS X
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?
Assignee: nobody → wcosta
Status: NEW → ASSIGNED
Flags: needinfo?(wcosta) → needinfo?(mjzffr)
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
Flags: needinfo?(mjzffr)
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?
Priority: -- → P3
We only waited 60s for startup of Firefox. So my patches for bug 1399592 and bug 1400786 should fix that failure.
Depends on: 1399592, 1400786
I would claim that this is fixed now with both dependent patches seeing landed.
Assignee: wcosta → hskupin
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox57: --- → fixed
Resolution: --- → FIXED
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.