Closed Bug 1818645 Opened 3 years ago Closed 2 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_clicking_on_a_multiline_link | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

task 2023-02-23T23:29:16.298Z] 23:29:16     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_clicking_on_a_multiline_link
[task 2023-02-23T23:29:16.298Z] 23:29:16     INFO -  1677194956298	Marionette	DEBUG	Accepted connection 145 from 127.0.0.1:50116
[task 2023-02-23T23:29:16.304Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d0600 for phase xpcom-will-shutdown
[task 2023-02-23T23:29:16.304Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d0600 for phase profile-before-change
[task 2023-02-23T23:29:16.308Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d0600 for phase quit-application-granted
[task 2023-02-23T23:29:16.325Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d2e00 for phase xpcom-will-shutdown
[task 2023-02-23T23:29:16.325Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d2e00 for phase profile-before-change
[task 2023-02-23T23:29:16.325Z] 23:29:16     INFO -  DEBUG: Adding blocker ContentParent: id=1e4d35d2e00 for phase quit-application-granted
...
[task 2023-02-23T23:35:36.594Z] 23:35:36     INFO -  console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 325))
[task 2023-02-23T23:37:36.615Z] 23:37:36     INFO -  1677195456616	addons.xpi	ERROR	System addon update list error SyntaxError: The URI is malformed.
[task 2023-02-23T23:38:08.863Z] 23:38:08     INFO -  DEBUG: Adding blocker Transaction (21) for phase places.sqlite#0: waiting for clients
[task 2023-02-23T23:38:08.864Z] 23:38:08     INFO -  DEBUG: Adding blocker places.sqlite#0: PlacesExpiration.jsm: expire (22) for phase places.sqlite#0: waiting for clients
[task 2023-02-23T23:38:08.866Z] 23:38:08     INFO -  DEBUG: Completed blocker Transaction (21) for phase places.sqlite#0: waiting for clients
[task 2023-02-23T23:38:08.866Z] 23:38:08     INFO -  DEBUG: Completed blocker places.sqlite#0: PlacesExpiration.jsm: expire (22) for phase places.sqlite#0: waiting for clients
[task 2023-02-23T23:40:16.489Z] 23:40:16     INFO -  1677195616490	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2023-02-23T23:40:16.492Z] 23:40:16     INFO -  1677195616492	Marionette	DEBUG	Closed connection 145
[task 2023-02-23T23:41:28.153Z] 23:41:28     INFO -  Failed to gather test failure debug: Please start a session
[task 2023-02-23T23:41:28.176Z] 23:41:28    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_clicking_on_a_multiline_link | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms
[task 2023-02-23T23:41:28.176Z] 23:41:28     INFO -  stacktrace:
[task 2023-02-23T23:41:28.176Z] 23:41:28     INFO -  	RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-02-23T23:41:28.176Z] 23:41:28     INFO -  	WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:181:5
[task 2023-02-23T23:41:28.176Z] 23:41:28     INFO -  	TimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:480:5
[task 2023-02-23T23:41:28.177Z] 23:41:28     INFO -  	bail@chrome://remote/content/marionette/sync.sys.mjs:211:19
[task 2023-02-23T23:41:28.177Z] 23:41:28     INFO -  Traceback (most recent call last):
[task 2023-02-23T23:41:28.177Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-02-23T23:41:28.177Z] 23:41:28     INFO -      testMethod()
[task 2023-02-23T23:41:28.177Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click.py", line 135, in test_clicking_on_a_multiline_link
[task 2023-02-23T23:41:28.178Z] 23:41:28     INFO -      self.marionette.navigate(test_html)
[task 2023-02-23T23:41:28.178Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1592, in navigate
[task 2023-02-23T23:41:28.178Z] 23:41:28     INFO -      self._send_message("WebDriver:Navigate", {"url": url})
[task 2023-02-23T23:41:28.178Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-02-23T23:41:28.178Z] 23:41:28     INFO -      return func(*args, **kwargs)
[task 2023-02-23T23:41:28.179Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\venv\lib\site-packages\marionette_driver\marionette.py", line 663, in _send_message
[task 2023-02-23T23:41:28.179Z] 23:41:28     INFO -      self._handle_error(err)
[task 2023-02-23T23:41:28.179Z] 23:41:28     INFO -    File "Z:\task_167719294753142\build\venv\lib\site-packages\marionette_driver\marionette.py", line 675, in _handle_error
[task 2023-02-23T23:41:28.179Z] 23:41:28     INFO -      raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2023-02-23T23:41:28.179Z] 23:41:28     INFO -  TEST-INFO took 731856ms

Marionette triggered a navigation but that never finished:
https://treeherder.mozilla.org/logviewer?job_id=406763866&repo=autoland&lineNumber=7851-7875

I don't know why and if we may be on the wrong browsing context. It's a problem that is very hard to reproduce.

Nevertheless similar to bug 1818415 we might want to reduce the default navigation timeout to just 30s or so.

See Also: → 1818415

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

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.