Closed Bug 1715629 Opened 2 years ago Closed 2 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py <test> | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms

Categories

(Testing :: Marionette, defect, P1)

defect

Tracking

(Fission Milestone:M7a, firefox-esr78 unaffected, firefox89 unaffected, firefox90 wontfix, firefox91 fixed)

RESOLVED FIXED
91 Branch
Fission Milestone M7a
Tracking Status
firefox-esr78 --- unaffected
firefox89 --- unaffected
firefox90 --- wontfix
firefox91 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell fixed:backout])

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


input[type=button] {\n  appeara ...  <input id=\"createDivButton\" type=\"button\" value=\"create a div\" onclick=\"addDelayedElement()\">\n\n\n</body></html>"}]
[task 2021-06-09T15:57:50.022Z] 15:57:50     INFO -  1623254270022	Marionette	DEBUG	498 -> [0,41,"Marionette:SetContext",{"value":"content"}]
[task 2021-06-09T15:57:50.023Z] 15:57:50     INFO -  1623254270022	Marionette	DEBUG	498 <- [1,41,null,{"value":null}]
[task 2021-06-09T15:57:50.025Z] 15:57:50    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms
[task 2021-06-09T15:57:50.026Z] 15:57:50     INFO -  stacktrace:
[task 2021-06-09T15:57:50.026Z] 15:57:50     INFO -  	WebDriverError@chrome://remote/content/marionette/error.js:181:5
[task 2021-06-09T15:57:50.026Z] 15:57:50     INFO -  	TimeoutError@chrome://remote/content/marionette/error.js:450:5
[task 2021-06-09T15:57:50.027Z] 15:57:50     INFO -  	bail@chrome://remote/content/marionette/sync.js:229:19
[task 2021-06-09T15:57:50.027Z] 15:57:50     INFO -  Traceback (most recent call last):
[task 2021-06-09T15:57:50.028Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 214, in run
[task 2021-06-09T15:57:50.028Z] 15:57:50     INFO -      testMethod()
[task 2021-06-09T15:57:50.029Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 530, in test_frameset_after_navigating_in_frame
[task 2021-06-09T15:57:50.029Z] 15:57:50     INFO -      self.marionette.go_back()
[task 2021-06-09T15:57:50.029Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1520, in go_back
[task 2021-06-09T15:57:50.030Z] 15:57:50     INFO -      self._send_message("WebDriver:Back")
[task 2021-06-09T15:57:50.030Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2021-06-09T15:57:50.030Z] 15:57:50     INFO -      return func(*args, **kwargs)
[task 2021-06-09T15:57:50.031Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\venv\lib\site-packages\marionette_driver\marionette.py", line 629, in _send_message
[task 2021-06-09T15:57:50.031Z] 15:57:50     INFO -      self._handle_error(err)
[task 2021-06-09T15:57:50.031Z] 15:57:50     INFO -    File "C:\Users\task_1623251978\build\venv\lib\site-packages\marionette_driver\marionette.py", line 651, in _handle_error
[task 2021-06-09T15:57:50.032Z] 15:57:50     INFO -      raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-06-09T15:57:50.032Z] 15:57:50     INFO -  TEST-INFO took 300382ms
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestBackForwardNavigation.test_frameset_after_navigating_in_frame | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py <test> | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms

Likely a regression from bug 1715300 which got backed out, in case you want to close it.

Whiteboard: [stockwell fixed:backout]

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #1)

Likely a regression from bug 1715300 which got backed out, in case you want to close it.

Thinking more about it it's unlikely caused by this bug given that it was already working fine before by manually specifying the preference. I assume that bug 1697905 is the culprit here which also got backed out on June 11th and matches the drop of failures.

To verify I applied the patch from bug 1715300 and pushed to try:
https://treeherder.mozilla.org/jobs?repo=try&revision=fe01b677833d8917ec8451432e909b78d6bddb9a

So I was wrong and it indeed started to fail with bug 1715300, which enabled BFCache in parent by default. Note that with the landing of my patch on bug 1704697 a month ago (May 11th), it was all fine. That means some other work for BFCache in parent during that time frame caused regressions in Marionette again.

Mostly affected here is TestBackForwardNavigation.test_frameset on Linux, and maybe it helps to find the cause of the regression.

The test fails since this merge commit:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=940a3ad12e3dc9b2809b02f6a8ac8e941a50d2a1&tochange=5c402eaa028455bb2c837bb0068741f43d566787

As such I assume it's related to the landing of bug 1696175. Peter can you please have a look?

Flags: needinfo?(peterv)

Henrik said that this can be reproduced using:
run mach marionette-test ... --run-until-failure
and disable all other tests in that file before
s/def test/def tst/

Here some exact steps:

  1. Open test_navigation.py in your editor
  2. Replace all def test_ with def tst_ except for test_frameset
  3. Run mach marionette-test --gecko-log - -vv testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py --enable-fission --setpref fission.bfcachInParent=tue --run-until-failure

Usually the failure happens after around the 10th iteration for a Linux opt artifact build.

So far I haven't managed to reproduce. I have tried with opt and debug builds.

Assignee: nobody → peterv
Fission Milestone: --- → M7a
Severity: S4 → S3
Status: NEW → ASSIGNED
Flags: needinfo?(peterv)
Priority: P5 → P1

Peter and Neha, it would be great to keep bug 1715884 for the fix and just mark this bug as being blocked by it.

Assignee: peterv → nobody
Status: ASSIGNED → NEW
Depends on: 1715884
Regressed by: 1696175

And to explain that, the assertion Overwriting an existing document channel is not always visible for this particular failure. So maybe there is something else that needs to be taken care of.

This occurred frequently after the first two times when bfcache-in-parent was enabled, but hasn't happened after the third time.
I expect this was fixed in bug 1715884

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