1908124 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py | single tracking bug

Status: RESOLVED INCOMPLETE

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2024-07-16T12:08:23.236Z] 12:08:23     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_execute_async_timeout_settimeout
[task 2024-07-16T12:08:27.417Z] 12:08:27     INFO -  Firefox is already running, but is not responding. To use Firefox, you must first close the existing Firefox process, restart your device, or use a different profile.
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_execute_async_timeout_settimeout | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Connection timed out after 360.0s)
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO - Traceback (most recent call last):
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -     testMethod()
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py", line 97, in test_execute_async_timeout_settimeout
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -     self.marionette.navigate(test_html)
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 1709, in navigate
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -     self._send_message("WebDriver:Navigate", {"url": url})
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -     m._handle_socket_failure()
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 853, in _handle_socket_failure
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -     reraise(
[task 2024-07-16T12:14:23.277Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 718, in reraise
[task 2024-07-16T12:14:23.278Z] 12:14:23     INFO -     raise value.with_traceback(tb)
[task 2024-07-16T12:14:23.278Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2024-07-16T12:14:23.278Z] 12:14:23     INFO -     return func(*args, **kwargs)
[task 2024-07-16T12:14:23.278Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 769, in _send_message
[task 2024-07-16T12:14:23.279Z] 12:14:23     INFO -     msg = self.client.request(name, params)
[task 2024-07-16T12:14:23.279Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/transport.py", line 382, in request
[task 2024-07-16T12:14:23.279Z] 12:14:23     INFO -     return self.receive()
[task 2024-07-16T12:14:23.279Z] 12:14:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/transport.py", line 218, in receive
[task 2024-07-16T12:14:23.280Z] 12:14:23     INFO -     raise socket.timeout(
[task 2024-07-16T12:14:23.280Z] 12:14:23     INFO - TEST-INFO took 360037ms
[task 2024-07-16T12:14:23.281Z] 12:14:23    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_execute_async_timeout_settimeout logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py\", line 231, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py\", line 18, in tearDown\n    self.marionette.timeout.reset()\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/timeout.py\", line 101, in reset\n    self.script = DEFAULT_SCRIPT_TIMEOUT\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/timeout.py\", line 54, in script\n    self._set(\"script\", sec)\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/timeout.py\", line 30, in _set\n    self._marionette._send_message(\"WebDriver:SetTimeouts\", {name: ms})\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py\", line 24, in _\n    return func(*args, **kwargs)\n  File \"/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py\", line 766, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_timeouts.TestTimeouts", "method_name": "test_execute_async_timeout_settimeout"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_execute_async_timeout_settimeout", "status": "ERROR"}
[task 2024-07-16T12:14:23.281Z] 12:14:23     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_get_timeout_fraction
[task 2024-07-16T12:14:23.281Z] 12:14:23     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmps99atlst.mozrunner
[task 2024-07-16T12:14:23.298Z] 12:14:23     INFO -  *** You are running in headless mode.
[task 2024-07-16T12:14:28.370Z] 12:14:28     INFO -  Firefox is already running, but is not responding. To use Firefox, you must first close the existing Firefox process, restart your device, or use a different profile.
[task 2024-07-16T12:15:23.474Z] 12:15:23     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_get_timeout_fraction | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors)
[task 2024-07-16T12:15:23.475Z] 12:15:23     INFO - Traceback (most recent call last):
[task 2024-07-16T12:15:23.476Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 179, in run
[task 2024-07-16T12:15:23.476Z] 12:15:23     INFO -     self.setUp()
[task 2024-07-16T12:15:23.477Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 399, in setUp
[task 2024-07-16T12:15:23.478Z] 12:15:23     INFO -     super(MarionetteTestCase, self).setUp()
[task 2024-07-16T12:15:23.479Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_harness/marionette_test/testcases.py", line 304, in setUp
[task 2024-07-16T12:15:23.479Z] 12:15:23     INFO -     self.marionette.start_session()
[task 2024-07-16T12:15:23.480Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2024-07-16T12:15:23.481Z] 12:15:23     INFO -     m._handle_socket_failure()
[task 2024-07-16T12:15:23.481Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 853, in _handle_socket_failure
[task 2024-07-16T12:15:23.482Z] 12:15:23     INFO -     reraise(
[task 2024-07-16T12:15:23.482Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 718, in reraise
[task 2024-07-16T12:15:23.483Z] 12:15:23     INFO -     raise value.with_traceback(tb)
[task 2024-07-16T12:15:23.484Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2024-07-16T12:15:23.484Z] 12:15:23     INFO -     return func(*args, **kwargs)
[task 2024-07-16T12:15:23.485Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 1363, in start_session
[task 2024-07-16T12:15:23.486Z] 12:15:23     INFO -     self.start_binary(timeout)
[task 2024-07-16T12:15:23.486Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 660, in start_binary
[task 2024-07-16T12:15:23.487Z] 12:15:23     INFO -     reraise(IOError, IOError(msg.format(timeout)), sys.exc_info()[2])
[task 2024-07-16T12:15:23.488Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/six.py", line 718, in reraise
[task 2024-07-16T12:15:23.489Z] 12:15:23     INFO -     raise value.with_traceback(tb)
[task 2024-07-16T12:15:23.489Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 650, in start_binary
[task 2024-07-16T12:15:23.489Z] 12:15:23     INFO -     self.raise_for_port(timeout=timeout)
[task 2024-07-16T12:15:23.490Z] 12:15:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.8/site-packages/marionette_driver/marionette.py", line 744, in raise_for_port
[task 2024-07-16T12:15:23.490Z] 12:15:23     INFO -     raise socket.timeout(
[task 2024-07-16T12:15:23.491Z] 12:15:23     INFO - TEST-INFO took 60198ms
[task 2024-07-16T12:15:23.491Z] 12:15:23     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_timeouts.py TestTimeouts.test_no_timeout_settimeout

Comment 1

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

The failure message comes from profileSelection.properties:
https://searchfox.org/mozilla-central/rev/f3e4b33a6122ce63bf81ae8c30cc5ac37458864b/toolkit/locales/en-US/chrome/mozapps/profile/profileSelection.properties#10

And it is used in nsAppRunner.cpp :: ProfileLockedDialog`:
https://searchfox.org/mozilla-central/rev/f3e4b33a6122ce63bf81ae8c30cc5ac37458864b/toolkit/xre/nsAppRunner.cpp#2713

So something might be wrong with the test test_reset_timeout so that it doesn't correctly shutdown Firefox.

Sadly the trace logs are turned off here so we miss further details about the shutdown. As first step it might be good to get trace logs enabled.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1908124&startday=2024-07-15&endday=2024-07-21&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Comment 4

[Intermittent Failures Robot]

1 failures were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Table

	no_variant
linux2404-x86_64/debug	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1908124&startday=2025-06-23&endday=2025-06-29&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Table

	no_variant
windows11-x86_64/opt	1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1908124&startday=2025-11-24&endday=2025-11-30&tree=all