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

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

(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?

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.

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

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