Closed
Bug 1675204
Opened 4 years ago
Closed 4 years ago
Intermittent [Tier 2] testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_about_newtab | TimeoutException:
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=320681121&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/AFcKTnU_S_quE8iibrSvrw/runs/0/artifacts/public/logs/live_backing.log
"TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_about_newtab
[task 2020-11-04T06:03:00.440Z] 06:03:00 INFO - 1604469780434 Marionette DEBUG 507 -> [0,25,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-11-04T06:03:00.440Z] 06:03:00 INFO - 1604469780434 Marionette DEBUG 507 <- [1,25,null,["6"]]
[task 2020-11-04T06:03:00.440Z] 06:03:00 INFO - 1604469780435 Marionette DEBUG 507 -> [0,26,"WebDriver:GetWindowHandles",{}]
[task 2020-11-04T06:03:00.440Z] 06:03:00 INFO - 1604469780435 Marionette DEBUG 507 <- [1,26,null,["17"]]
[task 2020-11-04T06:03:00.440Z] 06:03:00 INFO - 1604469780436 Marionette DEBUG 507 -> [0,27,"WebDriver:DeleteSession",{}]
[task 2020-11-04T06:03:00.441Z] 06:03:00 INFO - 1604469780436 Marionette TRACE [17] Parent actor created
[task 2020-11-04T06:03:00.441Z] 06:03:00 INFO - 1604469780437 Marionette DEBUG 507 <- [1,27,null,{"value":null}]
[task 2020-11-04T06:03:00.441Z] 06:03:00 INFO - 1604469780438 Marionette DEBUG Closed connection 507
...
INFO - 1604470080807 Marionette DEBUG 508 -> [0,37,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-04T06:08:00.808Z] 06:08:00 INFO - 1604470080807 Marionette DEBUG 508 <- [1,37,null,{"value":null}]
[task 2020-11-04T06:08:00.810Z] 06:08:00 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_about_newtab | TimeoutException:
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - stacktrace:
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - TimeoutError@chrome://marionette/content/error.js:450:5
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - bail@chrome://marionette/content/sync.js:220:19
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - Traceback (most recent call last):
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 214, in run
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - testMethod()
[task 2020-11-04T06:08:00.811Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 334, in test_about_newtab
[task 2020-11-04T06:08:00.812Z] 06:08:00 INFO - self.marionette.navigate(self.test_page_remote)
[task 2020-11-04T06:08:00.812Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1501, in navigate
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - self._send_message("WebDriver:Navigate", {"url": url})
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - return func(*args, **kwargs)
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\venv\lib\site-packages\marionette_driver\marionette.py", line 625, in _send_message
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - self._handle_error(err)
[task 2020-11-04T06:08:00.813Z] 06:08:00 INFO - File "C:\Users\task_1604464408\build\venv\lib\site-packages\marionette_driver\marionette.py", line 647, in _handle_error
[task 2020-11-04T06:08:00.814Z] 06:08:00 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-11-04T06:08:00.814Z] 06:08:00 INFO - TEST-INFO took 300370ms
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080810 Marionette DEBUG 508 -> [0,38,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080810 Marionette DEBUG 508 <- [1,38,null,{"value":null}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080811 Marionette DEBUG 508 -> [0,39,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080811 Marionette DEBUG 508 <- [1,39,null,{"value":null}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080812 Marionette DEBUG 508 -> [0,40,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080813 Marionette DEBUG 508 <- [1,40,null,{"value":null}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080813 Marionette DEBUG 508 -> [0,41,"WebDriver:GetWindowHandles",{}]
[task 2020-11-04T06:08:00.815Z] 06:08:00 INFO - 1604470080814 Marionette DEBUG 508 <- [1,41,null,["17","331"]]
[task 2020-11-04T06:08:00.817Z] 06:08:00 INFO - 1604470080815 Marionette DEBUG 508 -> [0,42,"WebDriver:SwitchToWindow",{"handle":"331","focus":true}]
[task 2020-11-04T06:08:00.826Z] 06:08:00 INFO - 1604470080819 Marionette DEBUG 508 <- [1,42,null,{"value":null}]
[task 2020-11-04T06:08:00.826Z] 06:08:00 INFO - 1604470080820 Marionette DEBUG 508 -> [0,43,"WebDriver:CloseWindow",{}]
[task 2020-11-04T06:08:00.836Z] 06:08:00 INFO - 1604470080828 Marionette TRACE Received DOM event TabClose for [object XULElement]
[task 2020-11-04T06:08:00.836Z] 06:08:00 INFO - 1604470080830 Marionette TRACE [331] Frame script unloaded
[task 2020-11-04T06:08:00.846Z] 06:08:00 INFO - 1604470080837 Marionette TRACE Received observer notification message-manager-disconnect
[task 2020-11-04T06:08:00.846Z] 06:08:00 INFO - 1604470080837 Marionette DEBUG 508 <- [1,43,null,["17"]]
[task 2020-11-04T06:08:00.846Z] 06:08:00 INFO - 1604470080839 Marionette DEBUG 508 -> [0,44,"WebDriver:SwitchToWindow",{"handle":"17","focus":true}]
[task 2020-11-04T06:08:00.846Z] 06:08:00 INFO - 1604470080840 Marionette DEBUG 508 <- [1,44,null,{"value":null}]
[task 2020-11-04T06:08:00.846Z] 06:08:00 INFO - 1604470080842 Marionette DEBUG 508 -> [0,45,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080842 Marionette DEBUG 508 <- [1,45,null,["6"]]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080843 Marionette DEBUG 508 -> [0,46,"WebDriver:GetWindowHandles",{}]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080843 Marionette DEBUG 508 <- [1,46,null,["17"]]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080843 Marionette DEBUG 508 -> [0,47,"WebDriver:DeleteSession",{}]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080844 Marionette TRACE [17] Parent actor created
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - 1604470080845 Marionette DEBUG 508 <- [1,47,null,{"value":null}]
[task 2020-11-04T06:08:00.847Z] 06:08:00 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_find_element_state_complete"```
|
||
Comment 1•4 years ago
|
||
The problematic lines are here:
https://treeherder.mozilla.org/logviewer?job_id=320681121&repo=mozilla-central&lineNumber=37799-37820
[task 2020-11-04T06:03:00.680Z] 06:03:00 INFO - 1604469780672 Marionette DEBUG 508 -> [0,25,"WebDriver:Navigate",{"url":"http://127.0.0.1:49918/test.html"}]
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780690 Marionette TRACE [331] Frame script loaded
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780690 Marionette TRACE Detected remoteness change. New browsing context: 331
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780691 Marionette TRACE [331] Child actor created for window id 508
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780691 Marionette TRACE Received message beforeunload for about:blank
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780692 Marionette TRACE [331] Parent actor created
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780693 Marionette TRACE Received message pagehide for about:blank
[task 2020-11-04T06:03:00.699Z] 06:03:00 INFO - 1604469780699 Marionette TRACE [331] Child actor created for window id 6442451138
[task 2020-11-04T06:03:00.702Z] 06:03:00 INFO - 1604469780700 Marionette TRACE [331] Frame script unloaded
[task 2020-11-04T06:03:00.712Z] 06:03:00 INFO - 1604469780709 Marionette TRACE Received message DOMContentLoaded for http://127.0.0.1:49918/test.html
[task 2020-11-04T06:03:00.712Z] 06:03:00 INFO - 1604469780709 Marionette TRACE [331] Parent actor created
[task 2020-11-04T06:03:00.712Z] 06:03:00 INFO - 1604469780709 Marionette TRACE Received message beforeunload for about:newtab
[task 2020-11-04T06:03:00.712Z] 06:03:00 INFO - 1604469780710 Marionette TRACE Received message pageshow for http://127.0.0.1:49918/test.html
[task 2020-11-04T06:03:00.712Z] 06:03:00 INFO - 1604469780710 Marionette TRACE Received message pagehide for about:newtab
[task 2020-11-04T06:03:00.974Z] 06:03:00 INFO - 1604469780972 Marionette TRACE [333] Child actor created for window id 154618822659
[task 2020-11-04T06:03:00.974Z] 06:03:00 INFO - 1604469780973 Marionette TRACE [333] Parent actor created
[task 2020-11-04T06:03:02.523Z] 06:03:02 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-04T06:03:02.528Z] 06:03:02 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-04T06:03:17.676Z] 06:03:17 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-04T06:03:17.676Z] 06:03:17 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-04T06:03:18.061Z] 06:03:18 INFO - DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-04T06:08:00.707Z] 06:08:00 INFO - 1604470080699 Marionette DEBUG 508 <- [1,25,{"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]
I would like to revisit this strange page load request when my patch on bug 1673823 landed. Maybe it already fixes it.
Blocks: marionette-fission, marionette-actor
Depends on: 1673823
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 3•4 years ago
|
||
A single failure so far that didn't happen again. I think that we can close this bug as incomplete for now.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
|
||
Updated•2 years ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 4•1 year ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in
before you can comment on or make changes to this bug.
Description
•