1482005 - Intermittent /webdriver/tests/* - setup error after UnknownErrorException: unknown error (500): connection refused

Status: RESOLVED INCOMPLETE

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ccoroiu [at] mozilla.com

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

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

task 2018-08-09T02:57:00.947Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept[capabilities0-alert-None] 
[task 2018-08-09T02:57:00.948Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept[capabilities0-confirm-True] 
[task 2018-08-09T02:57:00.948Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept[capabilities0-prompt-] 
[task 2018-08-09T02:57:00.948Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept_and_notify[capabilities0-alert-None] 
[task 2018-08-09T02:57:00.948Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept_and_notify[capabilities0-confirm-True] 
[task 2018-08-09T02:57:00.948Z] 02:57:00     INFO - TEST-PASS | /webdriver/tests/delete_cookie/user_prompts.py | test_accept_and_notify[capabilities0-prompt-] 
[task 2018-08-09T02:57:00.949Z] 02:57:00     INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/delete_cookie/user_prompts.py | test_dismiss[capabilities0-alert-None] - setup error
[task 2018-08-09T02:57:00.949Z] 02:57:00     INFO - capabilities = {'unhandledPromptBehavior': 'dismiss'}
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...b-platform.test,www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test'}}}, 'host': '127.0.0.1', 'port': 4444}
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO - request = <SubRequest 'session' for <Function 'test_dismiss[capabilities0-alert-None]'>>
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO - 
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO -     def session(capabilities, configuration, request):
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO -         """Create and start a session for a test that does not itself test session creation.
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.950Z] 02:57:00     INFO -         By default the session will stay open after each test, but we always try to start a
[task 2018-08-09T02:57:00.951Z] 02:57:00     INFO -         new one and assume that if that fails there is already a valid session. This makes it
[task 2018-08-09T02:57:00.951Z] 02:57:00     INFO -         possible to recover from some errors that might leave the session in a bad state, but
[task 2018-08-09T02:57:00.951Z] 02:57:00     INFO -         does not demand that we start a new session per test."""
[task 2018-08-09T02:57:00.951Z] 02:57:00     INFO -         global _current_session
[task 2018-08-09T02:57:00.951Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.952Z] 02:57:00     INFO -         # Update configuration capabilities with custom ones from the
[task 2018-08-09T02:57:00.952Z] 02:57:00     INFO -         # capabilities fixture, which can be set by tests
[task 2018-08-09T02:57:00.952Z] 02:57:00     INFO -         caps = copy.deepcopy(configuration["capabilities"])
[task 2018-08-09T02:57:00.952Z] 02:57:00     INFO -         caps.update(capabilities)
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -         caps = {"alwaysMatch": caps}
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -         # If there is a session with different capabilities active, end it now
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -         if _current_session is not None and (
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -                 caps != _current_session.requested_capabilities):
[task 2018-08-09T02:57:00.953Z] 02:57:00     INFO -             _current_session.end()
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -             _current_session = None
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -         if _current_session is None:
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -             _current_session = webdriver.Session(
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -                 configuration["host"],
[task 2018-08-09T02:57:00.954Z] 02:57:00     INFO -                 configuration["port"],
[task 2018-08-09T02:57:00.955Z] 02:57:00     INFO -                 capabilities=caps)
[task 2018-08-09T02:57:00.955Z] 02:57:00     INFO -         try:
[task 2018-08-09T02:57:00.955Z] 02:57:00     INFO - >           _current_session.start()
[task 2018-08-09T02:57:00.956Z] 02:57:00     INFO - 
[task 2018-08-09T02:57:00.956Z] 02:57:00     INFO - capabilities = {'unhandledPromptBehavior': 'dismiss'}
[task 2018-08-09T02:57:00.956Z] 02:57:00     INFO - caps       = {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'prefs...latform.test,www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test'}}, 'unhandledPromptBehavior': 'dismiss'}}
[task 2018-08-09T02:57:00.956Z] 02:57:00     INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox/firefox', 'pref...b-platform.test,www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test'}}}, 'host': '127.0.0.1', 'port': 4444}
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - request    = <SubRequest 'session' for <Function 'test_dismiss[capabilities0-alert-None]'>>
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - 
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - tests/web-platform/tests/webdriver/tests/support/fixtures.py:224: 
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:415: in start
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO -     value = self.send_command("POST", "session", body=body)
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2018-08-09T02:57:00.957Z] 02:57:00     INFO - 
[task 2018-08-09T02:57:00.958Z] 02:57:00     INFO - self = <Session (disconnected)>, method = 'POST', url = 'session'
[task 2018-08-09T02:57:00.958Z] 02:57:00     INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'binary': '/builds/worker/workspace/build/application/firefox...atform.test,www.web-platform.test,xn--n8j6ds53lwwkrqhv28a.web-platform.test'}}, 'unhandledPromptBehavior': 'dismiss'}}}
[task 2018-08-09T02:57:00.958Z] 02:57:00     INFO - 
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -     def send_command(self, method, url, body=None):
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -         """
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -             Send a command to the remote end and validate its success.
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -             :param method: HTTP method to use in request.
[task 2018-08-09T02:57:00.959Z] 02:57:00     INFO -             :param uri: "Command part" of the HTTP request URL,
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -                 e.g. `window/rect`.
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -             :param body: Optional body of the HTTP request.
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -             :return: `None` if the HTTP response body was empty, otherwise
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -                 the `value` field returned after parsing the response
[task 2018-08-09T02:57:00.960Z] 02:57:00     INFO -                 body as JSON.
[task 2018-08-09T02:57:00.961Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.961Z] 02:57:00     INFO -             :raises ValueError: If the response body does not contain a
[task 2018-08-09T02:57:00.961Z] 02:57:00     INFO -                 `value` key.
[task 2018-08-09T02:57:00.961Z] 02:57:00     INFO -             :raises error.WebDriverException: If the remote end returns
[task 2018-08-09T02:57:00.962Z] 02:57:00     INFO -                 an error.
[task 2018-08-09T02:57:00.962Z] 02:57:00     INFO -             """
[task 2018-08-09T02:57:00.962Z] 02:57:00     INFO -         response = self.transport.send(
[task 2018-08-09T02:57:00.962Z] 02:57:00     INFO -             method, url, body,
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -             encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -             session=self)
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -         if response.status != 200:
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -             err = error.from_response(response)
[task 2018-08-09T02:57:00.963Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.964Z] 02:57:00     INFO -             if isinstance(err, error.SessionNotCreatedException):
[task 2018-08-09T02:57:00.964Z] 02:57:00     INFO -                 # The driver could have already been deleted the session.
[task 2018-08-09T02:57:00.964Z] 02:57:00     INFO -                 self.session_id = None
[task 2018-08-09T02:57:00.964Z] 02:57:00     INFO -     
[task 2018-08-09T02:57:00.965Z] 02:57:00     INFO - >           raise err
[task 2018-08-09T02:57:00.965Z] 02:57:00     INFO - E           UnknownErrorException: unknown error (500): connection refused
[task 2018-08-09T02:57:00.965Z] 02:57:00     INFO -

Comment 1

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

Maybe a networking issue here. Lets wait for more data.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1482005&startday=2018-08-06&endday=2018-08-12&tree=all

Comment 3

[Intermittent Failures Robot]

2 failures in 2545 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=1482005&startday=2018-08-27&endday=2018-09-02&tree=all

Comment 4

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 5

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.