Open Bug 1728074 Opened 4 years ago Updated 6 days ago

Intermittent WD | <random> - setup error: webdriver.error.UnknownErrorException: unknown error (500): Process unexpectedly closed with status 1

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=349920872&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ShSccnBZSQOH1MVi198zww/runs/0/artifacts/public/logs/live_backing.log


[task 2021-08-30T07:43:43.007Z] 07:43:43     INFO - TEST-START | /webdriver/tests/element_click/bubbling.py
[task 2021-08-30T07:43:43.229Z] 07:43:43     INFO - STDOUT: ============================= test session starts ==============================
[task 2021-08-30T07:43:43.230Z] 07:43:43     INFO - STDOUT: platform darwin -- Python 3.7.9, pytest-6.1.1, py-1.5.2, pluggy-unknown -- /opt/worker/tasks/task_163030089473356/build/venv/bin/python
[task 2021-08-30T07:43:43.231Z] 07:43:43     INFO - STDOUT: rootdir: /opt/worker/tasks/task_163030089473356/build
[task 2021-08-30T07:43:43.232Z] 07:43:43     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2021-08-30T07:43:43.232Z] 07:43:43     INFO - STDOUT: collecting ... 
[task 2021-08-30T07:43:43.244Z] 07:43:43     INFO - STDOUT: collected 3 items
[task 2021-08-30T07:43:43.245Z] 07:43:43     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/element_click/bubbling.py::test_click_event_bubbles_to_parents 
[task 2021-08-30T07:43:43.247Z] 07:43:43     INFO - PID 5893 | 1630309423246	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner"], "binary": "/opt/worker/tasks/task_163030089473356/build/application/Firefox Nightly.app/Contents/MacOS/firefox"}}}}
[task 2021-08-30T07:43:43.248Z] 07:43:43     INFO - PID 5893 | 1630309423246	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2021-08-30T07:43:43.249Z] 07:43:43     INFO - PID 5893 | 1630309423246	geckodriver::capabilities	DEBUG	Found version 93.0a1
[task 2021-08-30T07:43:43.250Z] 07:43:43     INFO - PID 5893 | 1630309423247	geckodriver::browser	DEBUG	Backing up prefs to "/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner/user.geckodriver_backup_5"
[task 2021-08-30T07:43:43.259Z] 07:43:43     INFO - PID 5893 | 1630309423258	mozrunner::runner	INFO	Running command: "/opt/worker/tasks/task_163030089473356/build/application/Firefox Nightly.app/Contents/MacOS/firefox" "--marionette" "--profile" "/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner" "-foreground" "-no-remote"
[task 2021-08-30T07:43:43.260Z] 07:43:43     INFO - PID 5893 | 1630309423259	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2021-08-30T07:43:43.261Z] 07:43:43     INFO - PID 5893 | 1630309423259	geckodriver::marionette	TRACE	Connection refused (os error 61). Retrying in 100ms
[task 2021-08-30T07:43:43.314Z] 07:43:43     INFO - PID 5893 | *** You are running in headless mode.
<...>
[task 2021-08-30T07:43:47.491Z] 07:43:47     INFO - STDOUT: err        = <UnknownErrorException http_status=500>
[task 2021-08-30T07:43:47.491Z] 07:43:47     INFO - STDOUT: method     = 'POST'
[task 2021-08-30T07:43:47.492Z] 07:43:47     INFO - STDOUT: response   = <Response status=500 error=<UnknownErrorException http_status=500>>
[task 2021-08-30T07:43:47.492Z] 07:43:47     INFO - STDOUT: self       = <Session (disconnected)>
[task 2021-08-30T07:43:47.493Z] 07:43:47     INFO - STDOUT: timeout    = None
[task 2021-08-30T07:43:47.493Z] 07:43:47     INFO - STDOUT: url        = 'session'
[task 2021-08-30T07:43:47.494Z] 07:43:47     INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/client.py
[task 2021-08-30T07:43:47.494Z] 07:43:47     INFO - STDOUT: :604: UnknownErrorException
[task 2021-08-30T07:43:47.495Z] 07:43:47     INFO - STDOUT: =========================== short test summary info ============================
[task 2021-08-30T07:43:47.495Z] 07:43:47     INFO - STDOUT: ERROR tests/web-platform/tests/webdriver/tests/element_click/bubbling.py::test_click_event_bubbles_to_parents
[task 2021-08-30T07:43:47.496Z] 07:43:47     INFO - STDOUT: ========================== 2 passed, 1 error in 4.18s ==========================
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/element_click/bubbling.py | test_click_event_bubbles_to_parents - setup error: webdriver.error.UnknownErrorException: unknown error (500): Process unexpectedly closed with status 1
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - args = ()
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - kwargs = {'capabilities': {}, 'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile', '/var/folders/tf/...st': '127.0.0.1', 'port': 52114}, 'request': <SubRequest 'session' for <Function test_click_event_bubbles_to_parents>>}
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - request = <SubRequest 'session' for <Function test_click_event_bubbles_to_parents>>
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - setup = <function pytest_fixture_setup.<locals>.wrapper.<locals>.setup at 0x7fe912776d40>
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - finalizer = <function pytest_fixture_setup.<locals>.wrapper.<locals>.finalizer at 0x7fe912776dd0>
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO - 
[task 2021-08-30T07:43:47.503Z] 07:43:47     INFO -     def wrapper(*args, **kwargs):
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         loop = fixture_stripper.get_and_strip_from(FixtureStripper.EVENT_LOOP, kwargs)
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         request = fixture_stripper.get_and_strip_from(FixtureStripper.REQUEST, kwargs)
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -     
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         gen_obj = generator(*args, **kwargs)
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -     
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         async def setup():
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -             res = await gen_obj.__anext__()
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -             return res
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -     
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         def finalizer():
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -             """Yield again, to finalize."""
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -             async def async_finalizer():
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                 try:
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                     await gen_obj.__anext__()
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                 except StopAsyncIteration:
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                     pass
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                 else:
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                     msg = "Async generator fixture didn't stop."
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                     msg += "Yield only once."
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -                     raise ValueError(msg)
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -             loop.run_until_complete(async_finalizer())
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -     
[task 2021-08-30T07:43:47.504Z] 07:43:47     INFO -         request.addfinalizer(finalizer)
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - >       return loop.run_until_complete(setup())
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - 
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - args       = ()
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - finalizer  = <function pytest_fixture_setup.<locals>.wrapper.<locals>.finalizer at 0x7fe912776dd0>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - fixture_stripper = <pytest_asyncio.plugin.FixtureStripper object at 0x7fe91274c350>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - gen_obj    = <async_generator object session at 0x7fe912776cb0>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - generator  = <function session at 0x7fe9126f94d0>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - kwargs     = {'capabilities': {},
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -  'configuration': {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -                                                                     '/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner'],
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -                                                            'binary': '/opt/worker/tasks/task_163030089473356/build/application/Firefox '
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -                                                                      'Nightly.app/Contents/MacOS/firefox'}},
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -                    'host': '127.0.0.1',
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -                    'port': 52114},
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -  'request': <SubRequest 'session' for <Function test_click_event_bubbles_to_parents>>}
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - loop       = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - request    = <SubRequest 'session' for <Function test_click_event_bubbles_to_parents>>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - setup      = <function pytest_fixture_setup.<locals>.wrapper.<locals>.setup at 0x7fe912776d40>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - 
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:127: 
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - /Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/asyncio/base_events.py:587: in run_until_complete
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -     return future.result()
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -         future     = <Task finished coro=<pytest_fixture_setup.<locals>.wrapper.<locals>.setup() done, defined at /opt/worker/tasks/task_163030089473356/build/tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:109> exception=<UnknownErrorException http_status=500>>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -         new_task   = True
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -         self       = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:110: in setup
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -     res = await gen_obj.__anext__()
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO -         gen_obj    = <async_generator object session at 0x7fe912776cb0>
[task 2021-08-30T07:43:47.505Z] 07:43:47     INFO - tests/web-platform/tests/webdriver/tests/support/fixtures.py:117: in session
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -     _current_session.start()
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -         capabilities = {}
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -         caps       = {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                                  '/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner'],
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                         'binary': '/opt/worker/tasks/task_163030089473356/build/application/Firefox '
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                                   'Nightly.app/Contents/MacOS/firefox'}}}
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -         configuration = {'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                                   '/var/folders/tf/93bb5jv56vb7tmkplpdbr3_0000014/T/tmpea_nf7rr.mozrunner'],
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                          'binary': '/opt/worker/tasks/task_163030089473356/build/application/Firefox '
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -                                                    'Nightly.app/Contents/MacOS/firefox'}},
[task 2021-08-30T07:43:47.506Z] 07:43:47     INFO -  'host': '127.0.0.1',
<...>
[task 2021-08-30T07:43:47.508Z] 07:43:47     INFO - tests/web-platform/tests/tools/webdriver/webdriver/client.py:604: UnknownErrorException
[task 2021-08-30T07:43:47.509Z] 07:43:47     INFO - ..
[task 2021-08-30T07:43:47.509Z] 07:43:47     INFO - TEST-OK | /webdriver/tests/element_click/bubbling.py | took 4433ms
[task 2021-08-30T07:43:47.599Z] 07:43:47     INFO - Closing logging queue
[task 2021-08-30T07:43:47.600Z] 07:43:47     INFO - queue closed
[task 2021-08-30T07:43:47.601Z] 07:43:47     INFO - Starting runner
[task 2021-08-30T07:43:48.716Z] 07:43:48     INFO - PID 5905 | 1630309428102	geckodriver	INFO	Listening on 127.0.0.1:52179
[task 2021-08-30T07:43:48.716Z] 07:43:48     INFO - WebDriver HTTP server listening at http://127.0.0.1:52179/
[task 2021-08-30T07:43:48.718Z] 07:43:48     INFO - TEST-START | /webdriver/tests/element_click/center_point.py
Summary: Intermittent /webdriver/tests/element_click/bubbling.py | test_click_event_bubbles_to_parents - setup error: webdriver.error.UnknownErrorException: unknown error (500): Process unexpectedly closed with status 1 → Intermittent WD | <random> - setup error: webdriver.error.UnknownErrorException: unknown error (500): Process unexpectedly closed with status 1
See Also: → 1720748
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Duplicate of this bug: 1857852

All the recent intermittent failures were wrongly classified. I've fixed that for bug 1819763.

As such there we no failures with a status 1 exit code within the last month.

Status: REOPENED → RESOLVED
Closed: 3 years ago1 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Treeherder Bug Filer from comment #25)

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=444260258&repo=mozilla-central

This is a wrong classification again. Also the exit code with 127 doesn't match 1. It's as well bug 1819763.

Christian, as best is when you are using the search field of the log viewer and check for that failure message where exactly it is returned. Then observe the lines right before if some assertion is raised. That way you can find the real underlying issue.

Status: REOPENED → RESOLVED
Closed: 1 years ago1 years ago
Flags: needinfo?(ctuns)
Resolution: --- → INCOMPLETE

My apologies and thanks for the info.

Flags: needinfo?(ctuns)
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Treeherder Bug Filer from comment #28)

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=463004227&repo=mozilla-beta

This is just bug 1819763.

Status: REOPENED → RESOLVED
Closed: 1 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Duplicate of this bug: 1912657

We need trace logs (bug 1906355) to find out why the Mozilla specific tests causing Firefox to terminate abnormally.

Depends on: 1906355
Status: REOPENED → RESOLVED
Closed: 1 year ago4 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Treeherder Bug Filer from comment #59)

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=504448677&repo=mozilla-beta

This is bug 1819763.

Status: REOPENED → RESOLVED
Closed: 4 months ago3 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.