Open Bug 1675603 Opened 5 years ago Updated 10 days ago

Intermittent Mn TEST-UNEXPECTED-ERROR | <random_test> | TimeoutException: marionette_driver.errors.TimeoutException: Navigation timed out after 300000 ms

Categories

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

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 2 open bugs)

Details

(Keywords: intermittent-failure)

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


[task 2020-11-05T17:59:15.491Z] 17:59:15     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link
[task 2020-11-05T17:59:15.491Z] 17:59:15     INFO -  1604599155488	Marionette	DEBUG	200 <- [1,25,null,{"value":null}]
[task 2020-11-05T17:59:15.491Z] 17:59:15     INFO -  1604599155489	Marionette	DEBUG	Closed connection 200
[task 2020-11-05T17:59:15.493Z] 17:59:15     INFO -  1604599155490	Marionette	DEBUG	Accepted connection 201 from 127.0.0.1:50338
[task 2020-11-05T17:59:15.493Z] 17:59:15     INFO -  1604599155491	Marionette	DEBUG	201 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-11-05T17:59:15.495Z] 17:59:15     INFO -  1604599155492	Marionette	TRACE	[17] Frame script loaded
[task 2020-11-05T17:59:15.495Z] 17:59:15     INFO -  1604599155493	Marionette	DEBUG	201 <- [1,1,null,{"sessionId":"70cec750-1ada-4ea4-a32d-326f7cb54210","capabilities":{"browserName":"firefox","browserVersion":"84.0a ... p\\tmps_r_om.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-11-05T17:59:15.497Z] 17:59:15     INFO -  1604599155494	Marionette	DEBUG	201 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-11-05T17:59:15.497Z] 17:59:15     INFO -  1604599155494	Marionette	DEBUG	201 <- [1,2,null,{"value":null}]
[task 2020-11-05T17:59:15.497Z] 17:59:15     INFO -  1604599155495	Marionette	DEBUG	201 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-11-05T17:59:15.497Z] 17:59:15     INFO -  1604599155495	Marionette	DEBUG	201 <- [1,3,null,{"value":null}]
[task 2020-11-05T17:59:15.499Z] 17:59:15     INFO -  1604599155496	Marionette	DEBUG	201 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-11-05T17:59:15.499Z] 17:59:15     INFO -  1604599155496	Marionette	DEBUG	201 <- [1,4,null,{"value":null}]
[task 2020-11-05T17:59:15.499Z] 17:59:15     INFO -  1604599155497	Marionette	DEBUG	201 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-11-05T17:59:15.499Z] 17:59:15     INFO -  1604599155497	Marionette	DEBUG	201 <- [1,5,null,{"value":"6"}]
[task 2020-11-05T17:59:15.499Z] 17:59:15     INFO -  1604599155497	Marionette	DEBUG	201 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-11-05T17:59:15.500Z] 17:59:15     INFO -  1604599155498	Marionette	DEBUG	201 <- [1,6,null,["6"]]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155498	Marionette	DEBUG	201 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155498	Marionette	DEBUG	201 <- [1,7,null,{"value":"17"}]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155499	Marionette	DEBUG	201 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155499	Marionette	DEBUG	201 <- [1,8,null,["17"]]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155500	Marionette	DEBUG	201 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15     INFO -  1604599155500	Marionette	DEBUG	201 <- [1,9,null,["17"]]
[task 2020-11-05T17:59:15.503Z] 17:59:15     INFO -  1604599155500	Marionette	DEBUG	201 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-11-05T17:59:15.505Z] 17:59:15     INFO -  1604599155503	Marionette	TRACE	Received DOM event TabOpen for [object XULElement]
[task 2020-11-05T17:59:15.524Z] 17:59:15     INFO -  1604599155521	Marionette	TRACE	[160] Frame script loaded
[task 2020-11-05T17:59:15.542Z] 17:59:15     INFO -  1604599155534	Marionette	DEBUG	201 <- [1,10,null,{"handle":"160","type":"tab"}]
[task 2020-11-05T17:59:15.544Z] 17:59:15     INFO -  DEBUG: Adding blocker ContentParent: id=143c68b7000 for phase xpcom-will-shutdown
[task 2020-11-05T17:59:15.544Z] 17:59:15     INFO -  DEBUG: Adding blocker ContentParent: id=143c68b7000 for phase profile-before-change
[task 2020-11-05T17:59:15.549Z] 17:59:15     INFO -  1604599155546	Marionette	DEBUG	201 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.549Z] 17:59:15     INFO -  1604599155546	Marionette	DEBUG	201 <- [1,11,null,["17","160"]]
[task 2020-11-05T17:59:15.549Z] 17:59:15     INFO -  1604599155547	Marionette	DEBUG	201 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.549Z] 17:59:15     INFO -  1604599155547	Marionette	DEBUG	201 <- [1,12,null,["17","160"]]
[task 2020-11-05T17:59:15.551Z] 17:59:15     INFO -  1604599155550	Marionette	DEBUG	201 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"160","focus":true}]
[task 2020-11-05T17:59:15.561Z] 17:59:15     INFO -  1604599155556	Marionette	TRACE	Received DOM event TabSelect for [object XULElement]
[task 2020-11-05T17:59:15.566Z] 17:59:15     INFO -  1604599155563	Marionette	DEBUG	201 <- [1,13,null,{"value":null}]
[task 2020-11-05T17:59:15.566Z] 17:59:15     INFO -  1604599155563	Marionette	DEBUG	201 -> [0,14,"WebDriver:Navigate",{"url":"http://127.0.0.1:49874/clicks.html"}]
[task 2020-11-05T17:59:15.568Z] 17:59:15     INFO -  1604599155566	Marionette	TRACE	[160] MarionetteCommands actor created for window id 92341796865
[task 2020-11-05T17:59:15.587Z] 17:59:15     INFO -  1604599155580	Marionette	TRACE	[160] Frame script loaded
[task 2020-11-05T17:59:15.587Z] 17:59:15     INFO -  1604599155581	Marionette	TRACE	Detected remoteness change. New browsing context: 160
[task 2020-11-05T17:59:15.587Z] 17:59:15     INFO -  1604599155581	Marionette	TRACE	[160] MarionetteEvents actor created for window id 219
[task 2020-11-05T17:59:15.597Z] 17:59:15     INFO -  1604599155593	Marionette	TRACE	Received event beforeunload for about:blank
[task 2020-11-05T17:59:15.599Z] 17:59:15     INFO -  1604599155596	Marionette	TRACE	Received event pagehide for about:blank
[task 2020-11-05T17:59:15.601Z] 17:59:15     INFO -  1604599155599	Marionette	TRACE	[160] MarionetteEvents actor created for window id 92341796865
[task 2020-11-05T17:59:15.601Z] 17:59:15     INFO -  1604599155600	Marionette	TRACE	[160] MarionetteEvents actor created for window id 6442450974
[task 2020-11-05T17:59:15.603Z] 17:59:15     INFO -  1604599155601	Marionette	TRACE	[160] Frame script unloaded
[task 2020-11-05T17:59:15.613Z] 17:59:15     INFO -  1604599155612	Marionette	TRACE	Received event beforeunload for about:blank
[task 2020-11-05T17:59:15.613Z] 17:59:15     INFO -  1604599155612	Marionette	TRACE	Received event DOMContentLoaded for http://127.0.0.1:49874/clicks.html
[task 2020-11-05T17:59:15.615Z] 17:59:15     INFO -  1604599155614	Marionette	TRACE	Received event pageshow for http://127.0.0.1:49874/clicks.html
[task 2020-11-05T17:59:15.615Z] 17:59:15     INFO -  1604599155614	Marionette	TRACE	Received event pagehide for about:blank
[task 2020-11-05T17:59:26.139Z] 17:59:26     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:26.139Z] 17:59:26     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:34.817Z] 17:59:34     INFO -  DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-05T17:59:41.144Z] 17:59:41     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:41.146Z] 17:59:41     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T18:04:15.578Z] 18:04:15     INFO -  1604599455572	Marionette	DEBUG	201 <- [1,14,{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nTimeoutError@chrome://marionette/content/error.js:450:5\nbail@chrome://marionette/content/sync.js:220:19\n"},null]
[task 2020-11-05T18:04:15.578Z] 18:04:15     INFO -  1604599455574	Marionette	DEBUG	201 -> [0,15,"Marionette:GetContext",{}]
[task 2020-11-05T18:04:15.578Z] 18:04:15     INFO -  1604599455574	Marionette	DEBUG	201 <- [1,15,null,{"value":"content"}]
[task 2020-11-05T18:04:15.579Z] 18:04:15     INFO -  1604599455575	Marionette	DEBUG	201 -> [0,16,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-11-05T18:04:15.579Z] 18:04:15     INFO -  1604599455575	Marionette	DEBUG	201 <- [1,16,null,{"value":null}]
[task 2020-11-05T18:04:15.579Z] 18:04:15     INFO -  1604599455576	Marionette	DEBUG	201 -> [0,17,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-11-05T18:04:15.579Z] 18:04:15     INFO -  1604599455576	Marionette	TRACE	[6] MarionetteCommands actor created for window id 2
[task 2020-11-05T18:04:15.658Z] 18:04:15     INFO -  1604599455649	Marionette	DEBUG	201 <- [1,17,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQHCAYAAACjlsT7AAAgAElEQVR4nOzdf5Cc9X0n+P5z65a6orbKIcMfF+7sP7QLLuTaSrrO3jXh ... gmAAIAAABAMAEQAAAAAIIJgAAAAAAQTAAEAAAAgGACIAAAAAAEEwABAAAAIJgACAAAAADBBEAAAAAACCYAAgAAAECw/wO+p7y/KRMtEgAAAABJRU5ErkJggg=="}]
[task 2020-11-05T18:04:15.658Z] 18:04:15     INFO -  1604599455651	Marionette	DEBUG	201 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.659Z] 18:04:15     INFO -  1604599455651	Marionette	DEBUG	201 <- [1,18,null,{"value":null}]
[task 2020-11-05T18:04:15.659Z] 18:04:15     INFO -  1604599455651	Marionette	DEBUG	201 -> [0,19,"Marionette:GetContext",{}]
[task 2020-11-05T18:04:15.660Z] 18:04:15     INFO -  1604599455652	Marionette	DEBUG	201 <- [1,19,null,{"value":"content"}]
[task 2020-11-05T18:04:15.660Z] 18:04:15     INFO -  1604599455652	Marionette	DEBUG	201 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.660Z] 18:04:15     INFO -  1604599455652	Marionette	DEBUG	201 <- [1,20,null,{"value":null}]
[task 2020-11-05T18:04:15.660Z] 18:04:15     INFO -  1604599455653	Marionette	DEBUG	201 -> [0,21,"WebDriver:GetPageSource",{}]
[task 2020-11-05T18:04:15.661Z] 18:04:15     INFO -  1604599455654	Marionette	TRACE	[160] MarionetteCommands actor created for window id 6442450974
[task 2020-11-05T18:04:15.661Z] 18:04:15     INFO -  1604599455655	Marionette	DEBUG	201 <- [1,21,null,{"value":"<html><head>\n  <!-- This Source Code Form is subject to the terms of the Mozilla Public\n     - License ...    <a id=\"overflowLink\" href=\"test.html\">looooooooooong short looooooooooong</a>\n  </p>\n</div>\n\n\n\n</body></html>"}]
[task 2020-11-05T18:04:15.661Z] 18:04:15     INFO -  1604599455656	Marionette	DEBUG	201 -> [0,22,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.661Z] 18:04:15     INFO -  1604599455656	Marionette	DEBUG	201 <- [1,22,null,{"value":null}]
[task 2020-11-05T18:04:15.662Z] 18:04:15    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link | TimeoutException:
[task 2020-11-05T18:04:15.662Z] 18:04:15     INFO -  stacktrace:
[task 2020-11-05T18:04:15.662Z] 18:04:15     INFO -  	WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -  	TimeoutError@chrome://marionette/content/error.js:450:5
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -  	bail@chrome://marionette/content/sync.js:220:19
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -  Traceback (most recent call last):
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 195, in run
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -      self.setUp()
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click.py", line 486, in setUp
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -      self.marionette.navigate(self.test_page)
[task 2020-11-05T18:04:15.663Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1501, in navigate
[task 2020-11-05T18:04:15.664Z] 18:04:15     INFO -      self._send_message("WebDriver:Navigate", {"url": url})
[task 2020-11-05T18:04:15.664Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2020-11-05T18:04:15.664Z] 18:04:15     INFO -      return func(*args, **kwargs)
[task 2020-11-05T18:04:15.665Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 625, in _send_message
[task 2020-11-05T18:04:15.665Z] 18:04:15     INFO -      self._handle_error(err)
[task 2020-11-05T18:04:15.665Z] 18:04:15     INFO -    File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 647, in _handle_error
[task 2020-11-05T18:04:15.665Z] 18:04:15     INFO -      raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-11-05T18:04:15.665Z] 18:04:15     INFO -  TEST-INFO took 300167ms```

Some weird loading behavior. Lets observe the bug over the next days.

Didn't happen more than once and the last time it happened 11 days ago. Marking as incomplete.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago3 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link | TimeoutException: → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link | TimeoutException: marionette_driver.errors.TimeoutException: Navigation timed out after 300000 ms
Duplicate of this bug: 1829742
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link | TimeoutException: marionette_driver.errors.TimeoutException: Navigation timed out after 300000 ms → Intermittent Mn TEST-UNEXPECTED-ERROR | <random_test> | TimeoutException: marionette_driver.errors.TimeoutException: Navigation timed out after 300000 ms

Might be the same underlying reason as bug 1825501.

Status: REOPENED → NEW
See Also: → 1825501
Status: NEW → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → S3
Duplicate of this bug: 1965098
You need to log in before you can comment on or make changes to this bug.