Closed
Bug 1834856
Opened 2 years ago
Closed 2 years ago
Intermittent /webdriver/tests/classic/get_element_text/user_prompts.py | test_default[alert-None] - setup error: webdriver.error.TimeoutException: timeout (500): Failed to read marionette port
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1732076
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=416915226&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WrdIp48QRaOcDaheY-NEHQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-05-24T19:22:20.417Z] 19:22:20 INFO - TEST-PASS | /webdriver/tests/classic/get_element_text/user_prompts.py | test_ignore[capabilities0-prompt]
[task 2023-05-24T19:22:20.417Z] 19:22:20 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/classic/get_element_text/user_prompts.py | test_default[alert-None] - setup error: webdriver.error.TimeoutException: timeout (500): Failed to read marionette port
[task 2023-05-24T19:22:20.418Z] 19:22:20 INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-05-24T19:22:20.418Z] 19:22:20 INFO - request = <SubRequest 'session' for <Function test_default[alert-None]>>
[task 2023-05-24T19:22:20.419Z] 19:22:20 INFO - kwargs = {'capabilities': {}, 'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpr09ct1d9...rker/workspace/build/application/firefox/firefox'}}, 'host': '127.0.0.1', 'port': 41473, 'timeout_multiplier': 1, ...}}
[task 2023-05-24T19:22:20.419Z] 19:22:20 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7f1752288200>
[task 2023-05-24T19:22:20.419Z] 19:22:20 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7f1752288950>
[task 2023-05-24T19:22:20.420Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - @functools.wraps(func)
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - def _asyncgen_fixture_wrapper(
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - event_loop: asyncio.AbstractEventLoop, request: SubRequest, **kwargs: Any
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - ) -> _R:
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - gen_obj = func(**_add_kwargs(func, kwargs, event_loop, request))
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.421Z] 19:22:20 INFO - async def setup() -> _R:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - res = await gen_obj.__anext__()
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - return res
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - def finalizer() -> None:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - """Yield again, to finalize."""
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - async def async_finalizer() -> None:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - try:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - await gen_obj.__anext__()
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - except StopAsyncIteration:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - pass
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - else:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - msg = "Async generator fixture didn't stop."
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - msg += "Yield only once."
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - raise ValueError(msg)
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - event_loop.run_until_complete(async_finalizer())
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - > result = event_loop.run_until_complete(setup())
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7f1752288950>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - func = <function session at 0x7f1752e08cb0>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - gen_obj = <async_generator object session at 0x7f17522885f0>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - kwargs = {'capabilities': {},
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - '/tmp/tmpr09ct1d9.mozrunner'],
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}},
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'host': '127.0.0.1',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'port': 41473,
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'timeout_multiplier': 1,
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'webdriver': {'args': ['-vv'],
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'binary': '/builds/worker/fetches/geckodriver'}}}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - request = <SubRequest 'session' for <Function test_default[alert-None]>>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7f1752288200>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:293:
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - /usr/lib/python3.7/asyncio/base_events.py:579: in run_until_complete
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - return future.result()
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - future = <Task finished coro=<_wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup() done, defined at /builds/worker/workspace/build/tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:274> exception=<TimeoutException http_status=500>>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - new_task = True
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - self = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:275: in setup
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - res = await gen_obj.__anext__()
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - gen_obj = <async_generator object session at 0x7f17522885f0>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - tests/web-platform/tests/webdriver/tests/support/fixtures.py:136: in session
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - _current_session.start()
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - capabilities = {}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - caps = {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - '/tmp/tmpr09ct1d9.mozrunner'],
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}}}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - configuration = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - '/tmp/tmpr09ct1d9.mozrunner'],
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}},
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'host': '127.0.0.1',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'port': 41473,
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'timeout_multiplier': 1,
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'webdriver': {'args': ['-vv'], 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:558: in start
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - value = self.send_command("POST", "session", body=body)
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - '/tmp/tmpr09ct1d9.mozrunner'],
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}}}}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - self = <Session (disconnected)>
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - self = <Session (disconnected)>, method = 'POST', url = 'session'
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpr09ct1d9.mozrunner'], 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}}}}
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - timeout = None
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - def send_command(self, method, url, body=None, timeout=None):
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - """
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - Send a command to the remote end and validate its success.
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - :param method: HTTP method to use in request.
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - :param uri: "Command part" of the HTTP request URL,
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - e.g. `window/rect`.
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - :param body: Optional body of the HTTP request.
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - :return: `None` if the HTTP response body was empty, otherwise
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - the `value` field returned after parsing the response
[task 2023-05-24T19:22:20.422Z] 19:22:20 INFO - body as JSON.
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - :raises error.WebDriverException: If the remote end returns
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - an error.
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - :raises ValueError: If the response body does not contain a
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - `value` key.
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - """
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - response = self.transport.send(
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - method, url, body,
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - session=self, timeout=timeout)
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - if response.status != 200:
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - err = error.from_response(response)
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - if isinstance(err, error.InvalidSessionIdException):
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - # The driver could have already been deleted the session.
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - self.session_id = None
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - > raise err
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - E webdriver.error.TimeoutException: timeout (500): Failed to read marionette port
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - '/tmp/tmpr09ct1d9.mozrunner'],
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'}}}}
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - err = <TimeoutException http_status=500>
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - method = 'POST'
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - response = <Response status=500 error=<TimeoutException http_status=500>>
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - self = <Session (disconnected)>
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - timeout = None
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - url = 'session'
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO -
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:622: TimeoutException
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - ..
[task 2023-05-24T19:22:20.423Z] 19:22:20 INFO - TEST-OK | /webdriver/tests/classic/get_element_text/user_prompts.py | took 160525ms
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•2 years ago
|
||
That was a very slow startup of Firefox without any diagnostic output. Lets dupe to bug 1732076.
You need to log in
before you can comment on or make changes to this bug.
Description
•