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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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

Comment 2

[Intermittent Failures Robot]

20 failures in 3502 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 19
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-qr: 3
  • opt: 1
  • debug: 2
• windows10-64: 4
  • debug: 3
  • opt: 1
• linux1804-64: 3
  • opt: 3
• linux1804-64-shippable: 4
  • opt: 4
• linux1804-64-qr: 4
  • opt: 2
  • debug: 2
• linux1804-64-asan: 1
  • opt: 1
• windows10-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1715629&startday=2021-06-07&endday=2021-06-13&tree=all

Comment 3

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

(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

Comment 4

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

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.

Comment 5

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

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?

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

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/

Comment 7

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

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.

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

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

Comment 10

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

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

Comment 11

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

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.

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

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

Comment 13

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.