Closed Bug 1571426 Opened 2 months ago Closed 9 days ago

Intermittent /webdriver/tests/<random> | <random> - setup error [due to "CannotSendRequest"]

Categories

(Testing :: geckodriver, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [test isolation-])

Filed by: opoprus [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=259904343&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/WNCJ-YWOTSCCbPb9a9Fqzw/runs/0/artifacts/public/logs/live_backing.log


[task 2019-08-05T11:17:41.229Z] 11:17:41 INFO - TEST-START | /webdriver/tests/perform_actions/key.py
[task 2019-08-05T11:17:41.236Z] 11:17:41 INFO - PID 19431 | /builds/worker/workspace/build/tests/bin/geckodriver: error: Address already in use (os error 98)
[task 2019-08-05T11:17:41.236Z] 11:17:41 INFO - PID 19431 | geckodriver 0.24.0 (d681969e4480 2019-08-05 07:02 +0000)
[task 2019-08-05T11:17:41.236Z] 11:17:41 INFO - PID 19431 | WebDriver implementation for Firefox
[task 2019-08-05T11:17:41.236Z] 11:17:41 INFO - PID 19431 |
[task 2019-08-05T11:17:41.239Z] 11:17:41 INFO - PID 19431 | USAGE:
[task 2019-08-05T11:17:41.239Z] 11:17:41 INFO - PID 19431 | geckodriver [FLAGS] [OPTIONS]
[task 2019-08-05T11:17:41.239Z] 11:17:41 INFO - PID 19431 |
[task 2019-08-05T11:17:41.240Z] 11:17:41 INFO - PID 19431 | FLAGS:
[task 2019-08-05T11:17:41.240Z] 11:17:41 INFO - PID 19431 | --connect-existing Connect to an existing Firefox instance
[task 2019-08-05T11:17:41.240Z] 11:17:41 INFO - PID 19431 | -h, --help Prints this message
[task 2019-08-05T11:17:41.241Z] 11:17:41 INFO - PID 19431 | --jsdebugger Attach browser toolbox debugger for Firefox
[task 2019-08-05T11:17:41.241Z] 11:17:41 INFO - PID 19431 | -v Log level verbosity (-v for debug and -vv for trace level)
[task 2019-08-05T11:17:41.241Z] 11:17:41 INFO - PID 19431 | -V, --version Prints version and copying information
[task 2019-08-05T11:17:41.249Z] 11:17:41 INFO - PID 19431 |
[task 2019-08-05T11:17:41.250Z] 11:17:41 INFO - PID 19431 | OPTIONS:
[task 2019-08-05T11:17:41.258Z] 11:17:41 INFO - PID 19431 | -b, --binary <BINARY> Path to the Firefox binary
[task 2019-08-05T11:17:41.258Z] 11:17:41 INFO - PID 19431 | --log <LEVEL> Set Gecko log level [possible values: fatal, error, warn, info, config, debug,
[task 2019-08-05T11:17:41.269Z] 11:17:41 INFO - PID 19431 | trace]
[task 2019-08-05T11:17:41.269Z] 11:17:41 INFO - PID 19431 | --marionette-host <HOST> Host to use to connect to Gecko [default: 127.0.0.1]
[task 2019-08-05T11:17:41.284Z] 11:17:41 INFO - PID 19431 | --marionette-port <PORT> Port to use to connect to Gecko [default: system-allocated port]
[task 2019-08-05T11:17:41.285Z] 11:17:41 INFO - PID 19431 | --host <HOST> Host IP to use for WebDriver server [default: 127.0.0.1]
[task 2019-08-05T11:17:41.288Z] 11:17:41 INFO - PID 19431 | -p, --port <PORT> Port to use for WebDriver server [default: 4444]
[task 2019-08-05T11:17:41.465Z] 11:17:41 INFO - STDOUT: ============================= test session starts ==============================
[task 2019-08-05T11:17:41.465Z] 11:17:41 INFO - STDOUT: platform linux2 -- Python 2.7.12, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2019-08-05T11:17:41.466Z] 11:17:41 INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2019-08-05T11:17:41.466Z] 11:17:41 INFO - STDOUT: collecting ...
[task 2019-08-05T11:17:41.486Z] 11:17:41 INFO - STDOUT: collected 4 items
[task 2019-08-05T11:17:41.486Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/key.py::test_null_response_value
[task 2019-08-05T11:17:41.609Z] 11:17:41 INFO - STDOUT: ERROR
[task 2019-08-05T11:17:41.609Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/key.py::test_no_browsing_context
[task 2019-08-05T11:17:41.653Z] 11:17:41 INFO - STDOUT: ERROR
[task 2019-08-05T11:17:41.653Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/key.py::test_element_not_focused
[task 2019-08-05T11:17:41.701Z] 11:17:41 INFO - STDOUT: ERROR
[task 2019-08-05T11:17:41.702Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/key.py::test_backspace_erases_keys
[task 2019-08-05T11:17:41.742Z] 11:17:41 INFO - STDOUT: ERROR
[task 2019-08-05T11:17:41.743Z] 11:17:41 INFO - STDOUT: ==================================== ERRORS ====================================
[task 2019-08-05T11:17:41.744Z] 11:17:41 INFO - STDOUT: __________________ ERROR at setup of test_null_response_value __________________
[task 2019-08-05T11:17:41.746Z] 11:17:41 INFO - STDOUT: capabilities = {}
[task 2019-08-05T11:17:41.750Z] 11:17:41 INFO - STDOUT: configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...rm.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}, 'host': '127.0.0.1', 'port': 56320}
[task 2019-08-05T11:17:41.751Z] 11:17:41 INFO - STDOUT: request = <SubRequest 'session' for <Function 'test_null_response_value'>>
[task 2019-08-05T11:17:41.751Z] 11:17:41 INFO - STDOUT: @pytest.fixture(scope="function")
[task 2019-08-05T11:17:41.762Z] 11:17:41 INFO - STDOUT: def session(capabilities, configuration, request):
[task 2019-08-05T11:17:41.763Z] 11:17:41 INFO - STDOUT: """Create and start a session for a test that does not itself test session creation.
[task 2019-08-05T11:17:41.764Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.765Z] 11:17:41 INFO - STDOUT: By default the session will stay open after each test, but we always try to start a
[task 2019-08-05T11:17:41.765Z] 11:17:41 INFO - STDOUT: new one and assume that if that fails there is already a valid session. This makes it
[task 2019-08-05T11:17:41.766Z] 11:17:41 INFO - STDOUT: possible to recover from some errors that might leave the session in a bad state, but
[task 2019-08-05T11:17:41.767Z] 11:17:41 INFO - STDOUT: does not demand that we start a new session per test."""
[task 2019-08-05T11:17:41.768Z] 11:17:41 INFO - STDOUT: global _current_session
[task 2019-08-05T11:17:41.769Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.770Z] 11:17:41 INFO - STDOUT: # Update configuration capabilities with custom ones from the
[task 2019-08-05T11:17:41.770Z] 11:17:41 INFO - STDOUT: # capabilities fixture, which can be set by tests
[task 2019-08-05T11:17:41.771Z] 11:17:41 INFO - STDOUT: caps = copy.deepcopy(configuration["capabilities"])
[task 2019-08-05T11:17:41.772Z] 11:17:41 INFO - STDOUT: caps.update(capabilities)
[task 2019-08-05T11:17:41.772Z] 11:17:41 INFO - STDOUT: caps = {"alwaysMatch": caps}
[task 2019-08-05T11:17:41.773Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.773Z] 11:17:41 INFO - STDOUT: # If there is a session with different capabilities active, end it now
[task 2019-08-05T11:17:41.778Z] 11:17:41 INFO - STDOUT: if _current_session is not None and (
[task 2019-08-05T11:17:41.779Z] 11:17:41 INFO - STDOUT: caps != _current_session.requested_capabilities):
[task 2019-08-05T11:17:41.779Z] 11:17:41 INFO - STDOUT: _current_session.end()
[task 2019-08-05T11:17:41.780Z] 11:17:41 INFO - STDOUT: _current_session = None
[task 2019-08-05T11:17:41.781Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.782Z] 11:17:41 INFO - STDOUT: if _current_session is None:
[task 2019-08-05T11:17:41.782Z] 11:17:41 INFO - STDOUT: _current_session = webdriver.Session(
[task 2019-08-05T11:17:41.783Z] 11:17:41 INFO - STDOUT: configuration["host"],
[task 2019-08-05T11:17:41.784Z] 11:17:41 INFO - STDOUT: configuration["port"],
[task 2019-08-05T11:17:41.785Z] 11:17:41 INFO - STDOUT: capabilities=caps)
[task 2019-08-05T11:17:41.785Z] 11:17:41 INFO - STDOUT: try:
[task 2019-08-05T11:17:41.786Z] 11:17:41 INFO - STDOUT: > _current_session.start()
[task 2019-08-05T11:17:41.787Z] 11:17:41 INFO - STDOUT: capabilities = {}
[task 2019-08-05T11:17:41.787Z] 11:17:41 INFO - STDOUT: caps = {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'prefs...w.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}}
[task 2019-08-05T11:17:41.788Z] 11:17:41 INFO - STDOUT: configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...rm.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}, 'host': '127.0.0.1', 'port': 56320}
[task 2019-08-05T11:17:41.789Z] 11:17:41 INFO - STDOUT: request = <SubRequest 'session' for <Function 'test_null_response_value'>>
[task 2019-08-05T11:17:41.790Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/fixtures.py
[task 2019-08-05T11:17:41.790Z] 11:17:41 INFO - STDOUT: :150:
[task 2019-08-05T11:17:41.791Z] 11:17:41 INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2019-08-05T11:17:41.792Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/client.py
[task 2019-08-05T11:17:41.793Z] 11:17:41 INFO - STDOUT: :429: in start
[task 2019-08-05T11:17:41.793Z] 11:17:41 INFO - STDOUT: value = self.send_command("POST", "session", body=body)
[task 2019-08-05T11:17:41.794Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/client.py
[task 2019-08-05T11:17:41.795Z] 11:17:41 INFO - STDOUT: :471: in send_command
[task 2019-08-05T11:17:41.796Z] 11:17:41 INFO - STDOUT: session=self)
[task 2019-08-05T11:17:41.796Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/transport.py
[task 2019-08-05T11:17:41.797Z] 11:17:41 INFO - STDOUT: :175: in send
[task 2019-08-05T11:17:41.798Z] 11:17:41 INFO - STDOUT: response = self._request(method, uri, payload, headers)
[task 2019-08-05T11:17:41.799Z] 11:17:41 INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/transport.py
[task 2019-08-05T11:17:41.799Z] 11:17:41 INFO - STDOUT: :190: in _request
[task 2019-08-05T11:17:41.800Z] 11:17:41 INFO - STDOUT: self.connection.request(method, url, payload, headers)
[task 2019-08-05T11:17:41.801Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.802Z] 11:17:41 INFO - STDOUT: :1057: in request
[task 2019-08-05T11:17:41.802Z] 11:17:41 INFO - STDOUT: self._send_request(method, url, body, headers)
[task 2019-08-05T11:17:41.803Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.804Z] 11:17:41 INFO - STDOUT: :1097: in _send_request
[task 2019-08-05T11:17:41.804Z] 11:17:41 INFO - STDOUT: self.endheaders(body)
[task 2019-08-05T11:17:41.805Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.806Z] 11:17:41 INFO - STDOUT: :1053: in endheaders
[task 2019-08-05T11:17:41.807Z] 11:17:41 INFO - STDOUT: self._send_output(message_body)
[task 2019-08-05T11:17:41.807Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.808Z] 11:17:41 INFO - STDOUT: :897: in _send_output
[task 2019-08-05T11:17:41.809Z] 11:17:41 INFO - STDOUT: self.send(msg)
[task 2019-08-05T11:17:41.809Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.810Z] 11:17:41 INFO - STDOUT: :859: in send
[task 2019-08-05T11:17:41.810Z] 11:17:41 INFO - STDOUT: self.connect()
[task 2019-08-05T11:17:41.812Z] 11:17:41 INFO - STDOUT: /usr/lib/python2.7/httplib.py
[task 2019-08-05T11:17:41.812Z] 11:17:41 INFO - STDOUT: :836: in connect
[task 2019-08-05T11:17:41.813Z] 11:17:41 INFO - STDOUT: self.timeout, self.source_address)
[task 2019-08-05T11:17:41.813Z] 11:17:41 INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2019-08-05T11:17:41.814Z] 11:17:41 INFO - STDOUT: address = ('127.0.0.1', 56320), timeout = <object object at 0x7f77191710d0>
[task 2019-08-05T11:17:41.815Z] 11:17:41 INFO - STDOUT: source_address = None
[task 2019-08-05T11:17:41.816Z] 11:17:41 INFO - STDOUT: def create_connection(address, timeout=_GLOBAL_DEFAULT_TIMEOUT,
[task 2019-08-05T11:17:41.817Z] 11:17:41 INFO - STDOUT: source_address=None):
[task 2019-08-05T11:17:41.817Z] 11:17:41 INFO - STDOUT: """Connect to address and return the socket object.
[task 2019-08-05T11:17:41.819Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.819Z] 11:17:41 INFO - STDOUT: Convenience function. Connect to address (a 2-tuple (host, [task 2019-08-05T11:17:41.820Z] 11:17:41 INFO - STDOUT: port)) and return the socket object. Passing the optional
[task 2019-08-05T11:17:41.821Z] 11:17:41 INFO - STDOUT: timeout parameter will set the timeout on the socket instance
[task 2019-08-05T11:17:41.821Z] 11:17:41 INFO - STDOUT: before attempting to connect. If no timeout is supplied, the
[task 2019-08-05T11:17:41.822Z] 11:17:41 INFO - STDOUT: global default timeout setting returned by :func:getdefaulttimeout
[task 2019-08-05T11:17:41.823Z] 11:17:41 INFO - STDOUT: is used. If source_address is set it must be a tuple of (host, port)
[task 2019-08-05T11:17:41.823Z] 11:17:41 INFO - STDOUT: for the socket to bind as a source address before making the connection.
[task 2019-08-05T11:17:41.824Z] 11:17:41 INFO - STDOUT: A host of '' or port 0 tells the OS to use the default.
[task 2019-08-05T11:17:41.824Z] 11:17:41 INFO - STDOUT: """
[task 2019-08-05T11:17:41.825Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.827Z] 11:17:41 INFO - STDOUT: host, port = address
[task 2019-08-05T11:17:41.827Z] 11:17:41 INFO - STDOUT: err = None
[task 2019-08-05T11:17:41.829Z] 11:17:41 INFO - STDOUT: for res in getaddrinfo(host, port, 0, SOCK_STREAM):
[task 2019-08-05T11:17:41.829Z] 11:17:41 INFO - STDOUT: af, socktype, proto, canonname, sa = res
[task 2019-08-05T11:17:41.830Z] 11:17:41 INFO - STDOUT: sock = None
[task 2019-08-05T11:17:41.830Z] 11:17:41 INFO - STDOUT: try:
[task 2019-08-05T11:17:41.832Z] 11:17:41 INFO - STDOUT: sock = socket(af, socktype, proto)
[task 2019-08-05T11:17:41.832Z] 11:17:41 INFO - STDOUT: if timeout is not _GLOBAL_DEFAULT_TIMEOUT:
[task 2019-08-05T11:17:41.833Z] 11:17:41 INFO - STDOUT: sock.settimeout(timeout)
[task 2019-08-05T11:17:41.833Z] 11:17:41 INFO - STDOUT: if source_address:
[task 2019-08-05T11:17:41.835Z] 11:17:41 INFO - STDOUT: sock.bind(source_address)
[task 2019-08-05T11:17:41.836Z] 11:17:41 INFO - STDOUT: sock.connect(sa)
[task 2019-08-05T11:17:41.836Z] 11:17:41 INFO - STDOUT: return sock
[task 2019-08-05T11:17:41.837Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.837Z] 11:17:41 INFO - STDOUT: except error as _:
[task 2019-08-05T11:17:41.839Z] 11:17:41 INFO - STDOUT: err = _
[task 2019-08-05T11:17:41.840Z] 11:17:41 INFO - STDOUT: if sock is not None:
[task 2019-08-05T11:17:41.840Z] 11:17:41 INFO - STDOUT: sock.close()
[task 2019-08-05T11:17:41.841Z] 11:17:41 INFO - STDOUT:
[task 2019-08-05T11:17:41.842Z] 11:17:41 INFO - STDOUT: if err is not None:
[task 2019-08-05T11:17:41.843Z] 11:17:41 INFO - STDOUT: > raise err
[task 2019-08-05T11:17:41.843Z] 11:17:41 INFO - STDOUT: E error: [Errno 111] Connection refused
[task 2019-08-05T11:17:41.844Z] 11:17:41 INFO - STDOUT: _ = error(111, 'Connection refused')
[task 2019-08-05T11:17:41.848Z] 11:17:41 INFO - STDOUT: address = ('127.0.0.1', 56320)
[task 2019-08-05T11:17:41.849Z] 11:17:41 INFO - STDOUT: af = 2
[task 2019-08-05T11:17:41.850Z] 11:17:41 INFO - STDOUT: canonname = ''
[task 2019-08-05T11:17:41.851Z] 11:17:41 INFO - STDOUT: err = error(111, 'Connection refused')
[task 2019-08-05T11:17:41.855Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.855Z] 11:17:41 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/perform_actions/key.py | test_null_response_value - setup error
[task 2019-08-05T11:17:41.855Z] 11:17:41 INFO - capabilities = {}
[task 2019-08-05T11:17:41.855Z] 11:17:41 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...rm.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}, 'host': '127.0.0.1', 'port': 56320}
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - request = <SubRequest 'session' for <Function 'test_null_response_value'>>
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - @pytest.fixture(scope="function")
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - def session(capabilities, configuration, request):
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - """Create and start a session for a test that does not itself test session creation.
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - By default the session will stay open after each test, but we always try to start a
[task 2019-08-05T11:17:41.856Z] 11:17:41 INFO - new one and assume that if that fails there is already a valid session. This makes it
[task 2019-08-05T11:17:41.857Z] 11:17:41 INFO - possible to recover from some errors that might leave the session in a bad state, but
[task 2019-08-05T11:17:41.857Z] 11:17:41 INFO - does not demand that we start a new session per test."""
[task 2019-08-05T11:17:41.857Z] 11:17:41 INFO - global _current_session
[task 2019-08-05T11:17:41.857Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.857Z] 11:17:41 INFO - # Update configuration capabilities with custom ones from the
[task 2019-08-05T11:17:41.858Z] 11:17:41 INFO - # capabilities fixture, which can be set by tests
[task 2019-08-05T11:17:41.858Z] 11:17:41 INFO - caps = copy.deepcopy(configuration["capabilities"])
[task 2019-08-05T11:17:41.858Z] 11:17:41 INFO - caps.update(capabilities)
[task 2019-08-05T11:17:41.859Z] 11:17:41 INFO - caps = {"alwaysMatch": caps}
[task 2019-08-05T11:17:41.859Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.859Z] 11:17:41 INFO - # If there is a session with different capabilities active, end it now
[task 2019-08-05T11:17:41.860Z] 11:17:41 INFO - if _current_session is not None and (
[task 2019-08-05T11:17:41.861Z] 11:17:41 INFO - caps != _current_session.requested_capabilities):
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO - _current_session.end()
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO - _current_session = None
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO - if _current_session is None:
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO - _current_session = webdriver.Session(
[task 2019-08-05T11:17:41.862Z] 11:17:41 INFO - configuration["host"],
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - configuration["port"],
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - capabilities=caps)
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - try:
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - > _current_session.start()
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - capabilities = {}
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - caps = {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'prefs...w.xn--n8j6ds53lwwkrqhv28a.web-platform.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}}
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...rm.test,xn--lve-6lad.www2.not-web-platform.test,www2.www.not-web-platform.test'}}}, 'host': '127.0.0.1', 'port': 56320}
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - request = <SubRequest 'session' for <Function 'test_null_response_value'>>
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - tests/web-platform/tests/webdriver/tests/support/fixtures.py:150:
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:429: in start
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - value = self.send_command("POST", "session", body=body)
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:471: in send_command
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - session=self)
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - tests/web-platform/tests/tools/webdriver/webdriver/transport.py:175: in send
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - response = self._request(method, uri, payload, headers)
[task 2019-08-05T11:17:41.863Z] 11:17:41 INFO - tests/web-platform/tests/tools/webdriver/webdriver/transport.py:190: in _request
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - self.connection.request(method, url, payload, headers)
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:1057: in request
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - self._send_request(method, url, body, headers)
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:1097: in _send_request
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - self.endheaders(body)
[task 2019-08-05T11:17:41.864Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:1053: in endheaders
[task 2019-08-05T11:17:41.865Z] 11:17:41 INFO - self._send_output(message_body)
[task 2019-08-05T11:17:41.865Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:897: in _send_output
[task 2019-08-05T11:17:41.865Z] 11:17:41 INFO - self.send(msg)
[task 2019-08-05T11:17:41.865Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:859: in send
[task 2019-08-05T11:17:41.865Z] 11:17:41 INFO - self.connect()
[task 2019-08-05T11:17:41.866Z] 11:17:41 INFO - /usr/lib/python2.7/httplib.py:836: in connect
[task 2019-08-05T11:17:41.866Z] 11:17:41 INFO - self.timeout, self.source_address)
[task 2019-08-05T11:17:41.866Z] 11:17:41 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2019-08-05T11:17:41.866Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - address = ('127.0.0.1', 56320), timeout = <object object at 0x7f77191710d0>
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - source_address = None
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - def create_connection(address, timeout=_GLOBAL_DEFAULT_TIMEOUT,
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - source_address=None):
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - """Connect to address and return the socket object.
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.867Z] 11:17:41 INFO - Convenience function. Connect to address (a 2-tuple (host, [task 2019-08-05T11:17:41.868Z] 11:17:41 INFO - port)) and return the socket object. Passing the optional
[task 2019-08-05T11:17:41.868Z] 11:17:41 INFO - timeout parameter will set the timeout on the socket instance
[task 2019-08-05T11:17:41.868Z] 11:17:41 INFO - before attempting to connect. If no timeout is supplied, the
[task 2019-08-05T11:17:41.869Z] 11:17:41 INFO - global default timeout setting returned by :func:getdefaulttimeout
[task 2019-08-05T11:17:41.869Z] 11:17:41 INFO - is used. If source_address is set it must be a tuple of (host, port)
[task 2019-08-05T11:17:41.869Z] 11:17:41 INFO - for the socket to bind as a source address before making the connection.
[task 2019-08-05T11:17:41.870Z] 11:17:41 INFO - A host of '' or port 0 tells the OS to use the default.
[task 2019-08-05T11:17:41.870Z] 11:17:41 INFO - """
[task 2019-08-05T11:17:41.870Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - host, port = address
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - err = None
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - for res in getaddrinfo(host, port, 0, SOCK_STREAM):
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - af, socktype, proto, canonname, sa = res
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - sock = None
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - try:
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - sock = socket(af, socktype, proto)
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - if timeout is not _GLOBAL_DEFAULT_TIMEOUT:
[task 2019-08-05T11:17:41.871Z] 11:17:41 INFO - sock.settimeout(timeout)
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - if source_address:
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - sock.bind(source_address)
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - sock.connect(sa)
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - return sock
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - except error as _:
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - err = _
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - if sock is not None:
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - sock.close()
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - if err is not None:
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - > raise err
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - E error: [Errno 111] Connection refused
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - _ = error(111, 'Connection refused')
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - address = ('127.0.0.1', 56320)
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - af = 2
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - canonname = ''
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - err = error(111, 'Connection refused')
[task 2019-08-05T11:17:41.872Z] 11:17:41 INFO - host = '127.0.0.1'
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - port = 56320
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - proto = 6
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - res = (2, 1, 6, '', ('127.0.0.1', 56320))
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - sa = ('127.0.0.1', 56320)
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - sock = <socket._socketobject object at 0x7f770fa96c20>
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - socktype = 1
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - source_address = None
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - timeout = <object object at 0x7f77191710d0>
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - /usr/lib/python2.7/socket.py:575: error
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO -
[task 2019-08-05T11:17:41.873Z] 11:17:41 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/perform_actions/key.py | test_no_browsing_context - setup error

Summary: Intermittent /webdriver/tests/perform_actions/key.py | test_null_response_value - setup error → Intermittent /webdriver/tests/perform_actions/key.py | test_null_response_value - setup error [due to "CannotSendRequest"]
Whiteboard: [test isolation]
Summary: Intermittent /webdriver/tests/perform_actions/key.py | test_null_response_value - setup error [due to "CannotSendRequest"] → Intermittent /webdriver/tests/<random> | <random> - setup error [due to "CannotSendRequest"]

(In reply to Andreas Tolfsen 「:ato」 from bug 1574075 comment #1)

Perhaps we should consider binding to 0 to have the system
atomically allocate the port?

Are we doing that with wdspec tests and geckodriver? I thought always uses a different port, or is that only Selenium which is doing that?

Flags: needinfo?(ato)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #3)

(In reply to Andreas Tolfsen 「:ato」 from bug 1574075 comment #1)

Perhaps we should consider binding to 0 to have the system
atomically allocate the port?

Are we doing that with wdspec tests and geckodriver? I thought
always uses a different port, or is that only Selenium which is
doing that?

To my recollection, Selenium clients randomise the port ahead of
starting the process which can intermittently cause race conditions.
As can be seen in this log we don’t do that with wdspec.

I’ve filed bug 1574097 about binding to port 0.

Depends on: 1574097
Flags: needinfo?(ato)
Status: NEW → RESOLVED
Closed: 9 days ago
Resolution: --- → INCOMPLETE
Whiteboard: [test isolation] → [test isolation-]
You need to log in before you can comment on or make changes to this bug.