Closed
Bug 1849394
Opened 2 years ago
Closed 2 years ago
Intermittent /webdriver/tests/classic/forward/user_prompts.py | test_dismiss_and_notify[capabilities0-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 1794745
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=426487832&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/STT4lHsjSlWOKIUR-oydaQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - TEST-PASS | /webdriver/tests/classic/forward/user_prompts.py | test_dismiss[capabilities0-prompt]
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/classic/forward/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - setup error: webdriver.error.TimeoutException: timeout (500): Failed to read marionette port
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - request = <SubRequest 'session' for <Function test_dismiss_and_notify[capabilities0-alert-None]>>
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - kwargs = {'capabilities': {'unhandledPromptBehavior': 'dismiss and notify'}, 'configuration': {'browser': {'args': ['--profile'...'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpd9ppvsf9.mozrunner']}}, 'host': '127.0.0.1', 'port': 49161, ...}}
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7fa801d7d950>
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7fa801d7d7a0>
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - @functools.wraps(func)
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - def _asyncgen_fixture_wrapper(
[task 2023-08-18T16:10:36.719Z] 16:10:36 INFO - event_loop: asyncio.AbstractEventLoop, request: SubRequest, **kwargs: Any
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - ) -> _R:
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - gen_obj = func(**_add_kwargs(func, kwargs, event_loop, request))
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - async def setup() -> _R:
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - res = await gen_obj.__anext__()
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - return res
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - def finalizer() -> None:
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - """Yield again, to finalize."""
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - async def async_finalizer() -> None:
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - try:
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - await gen_obj.__anext__()
[task 2023-08-18T16:10:36.720Z] 16:10:36 INFO - except StopAsyncIteration:
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - pass
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - else:
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - msg = "Async generator fixture didn't stop."
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - msg += "Yield only once."
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - raise ValueError(msg)
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - event_loop.run_until_complete(async_finalizer())
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - > result = event_loop.run_until_complete(setup())
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7fa801d7d7a0>
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - func = <function session at 0x7fa802705b90>
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - gen_obj = <async_generator object session at 0x7fa801d7e3b0>
[task 2023-08-18T16:10:36.721Z] 16:10:36 INFO - kwargs = {'capabilities': {'unhandledPromptBehavior': 'dismiss and notify'},
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'configuration': {'browser': {'args': ['--profile',
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner'],
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'},
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner']}},
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'host': '127.0.0.1',
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'port': 49161,
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'timeout_multiplier': 1,
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'webdriver': {'args': ['-vv',
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - '--binary',
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - '/builds/worker/workspace/build/application/firefox/firefox'],
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - 'binary': '/builds/worker/fetches/geckodriver'}}}
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - request = <SubRequest 'session' for <Function test_dismiss_and_notify[capabilities0-alert-None]>>
[task 2023-08-18T16:10:36.722Z] 16:10:36 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7fa801d7d950>
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:293:
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - /usr/lib/python3.7/asyncio/base_events.py:579: in run_until_complete
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - return future.result()
[task 2023-08-18T16:10:36.723Z] 16:10:36 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-08-18T16:10:36.723Z] 16:10:36 INFO - new_task = True
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - self = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:275: in setup
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - res = await gen_obj.__anext__()
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - gen_obj = <async_generator object session at 0x7fa801d7e3b0>
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - tests/web-platform/tests/webdriver/tests/support/fixtures.py:136: in session
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - _current_session.start()
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - capabilities = {'unhandledPromptBehavior': 'dismiss and notify'}
[task 2023-08-18T16:10:36.723Z] 16:10:36 INFO - caps = {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner']},
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'unhandledPromptBehavior': 'dismiss and notify'}}
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - configuration = {'browser': {'args': ['--profile', '/tmp/tmpd9ppvsf9.mozrunner'],
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'binary': '/builds/worker/workspace/build/application/firefox/firefox'},
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner']}},
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'host': '127.0.0.1',
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'port': 49161,
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'timeout_multiplier': 1,
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'webdriver': {'args': ['-vv',
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - '--binary',
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - '/builds/worker/workspace/build/application/firefox/firefox'],
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - 'binary': '/builds/worker/fetches/geckodriver'}}
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:558: in start
[task 2023-08-18T16:10:36.724Z] 16:10:36 INFO - value = self.send_command("POST", "session", body=body)
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner']},
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - 'unhandledPromptBehavior': 'dismiss and '
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - 'notify'}}}
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - self = <Session (disconnected)>
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - self = <Session (disconnected)>, method = 'POST', url = 'session'
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile', '/tmp/tmpd9ppvsf9.mozrunner']}, 'unhandledPromptBehavior': 'dismiss and notify'}}}
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - timeout = None
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - def send_command(self, method, url, body=None, timeout=None):
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - """
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO - Send a command to the remote end and validate its success.
[task 2023-08-18T16:10:36.725Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :param method: HTTP method to use in request.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :param uri: "Command part" of the HTTP request URL,
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - e.g. `window/rect`.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :param body: Optional body of the HTTP request.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :return: `None` if the HTTP response body was empty, otherwise
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - the `value` field returned after parsing the response
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - body as JSON.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :raises error.WebDriverException: If the remote end returns
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - an error.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - :raises ValueError: If the response body does not contain a
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - `value` key.
[task 2023-08-18T16:10:36.726Z] 16:10:36 INFO - """
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - response = self.transport.send(
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - method, url, body,
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - session=self, timeout=timeout)
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - if response.status != 200:
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - err = error.from_response(response)
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - if isinstance(err, error.InvalidSessionIdException):
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - # The driver could have already been deleted the session.
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - self.session_id = None
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.727Z] 16:10:36 INFO - > raise err
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - E webdriver.error.TimeoutException: timeout (500): Failed to read marionette port
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - '/tmp/tmpd9ppvsf9.mozrunner']},
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - 'unhandledPromptBehavior': 'dismiss and '
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - 'notify'}}}
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - err = <TimeoutException http_status=500>
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - method = 'POST'
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - response = <Response status=500 error=<TimeoutException http_status=500>>
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - self = <Session (disconnected)>
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - timeout = None
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - url = 'session'
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO -
[task 2023-08-18T16:10:36.728Z] 16:10:36 INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:622: TimeoutException
[task 2023-08-18T16:10:36.731Z] 16:10:36 INFO - ........
[task 2023-08-18T16:10:36.731Z] 16:10:36 INFO - TEST-OK | /webdriver/tests/classic/forward/user_prompts.py | took 163977ms
|
||
Comment 1•2 years ago
|
||
This is a very slow startup of Firefox, and basically a dupe of bug 1794745.
You need to log in
before you can comment on or make changes to this bug.
Description
•