Open Bug 1400780 Opened 2 years ago Updated Last month

Intermittent test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | AssertionError: Non private browsing windows should have

Categories

(Testing :: Firefox UI Tests, defect, P5)

Version 3
defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=131688717&repo=autoland

[object Object]

07:25:23     INFO -  1505719523583	Marionette	TRACE	1 -> [0,218,"setContext",{"value":"chrome"}]
07:25:23     INFO -  1505719523583	Marionette	TRACE	1 <- [1,218,null,{}]
07:25:23     INFO -  1505719523585	Marionette	TRACE	1 -> [0,219,"getContext",{}]
07:25:23     INFO -  1505719523585	Marionette	TRACE	1 <- [1,219,null,{"value":"chrome"}]
07:25:23     INFO -  1505719523586	Marionette	TRACE	1 -> [0,220,"setContext",{"value":"content"}]
07:25:23     INFO -  1505719523587	Marionette	TRACE	1 <- [1,220,null,{}]
07:25:23     INFO -  1505719523592	Marionette	TRACE	1 -> [0,221,"getPageSource",{}]
07:25:23     INFO -  1505719523596	Marionette	TRACE	1 <- [1,221,null,{"value":"<html><head></head><body></body></html>"}]
07:25:23     INFO -  1505719523598	Marionette	TRACE	1 -> [0,222,"setContext",{"value":"chrome"}]
07:25:23     INFO -  1505719523598	Marionette	TRACE	1 <- [1,222,null,{}]
07:25:23     INFO - TEST-UNEXPECTED-FAIL | test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | AssertionError: Non private browsing windows should have
07:25:23     INFO -                          been restored. Expected set([('http://127.0.0.1:49255/layout/mozilla_organizations.html', 'http://127.0.0.1:49255/layout/mozilla_community.html'), ('http://127.0.0.1:49255/layout/mozilla_governance.html', 'http://127.0.0.1:49255/layout/mozilla_grants.html'), ('http://127.0.0.1:49255/layout/mozilla.html',)]), got set([(u'http://127.0.0.1:49255/layout/mozilla_organizations.html', u'http://127.0.0.1:49255/layout/mozilla_community.html'), (u'about:blank',), (u'about:newtab',)]).
07:25:23     INFO - Traceback (most recent call last):
07:25:23     INFO -   File "Z:\task_1505718402\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 156, in run
07:25:23     INFO -     testMethod()
07:25:23     INFO -   File "Z:\task_1505718402\build\tests\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py", line 202, in test_restore_with_restart
07:25:23     INFO -     """.format(self.test_windows, current_windows_set))
As it looks like the check for open windows is done too early, and for a restart we do not wait for all the windows being restored. Instead we run the tests right after `sessionrestore-windows-restored` has been fired.

Mike, this is a high frequent failure. Maybe you could tell us if there is another event we have to wait for before continuing the test after a restart?
Flags: needinfo?(mdeboer)
Component: Marionette → Firefox UI Tests
QA Contact: hskupin
(In reply to Henrik Skupin (:whimboo) from comment #30)
> As it looks like the check for open windows is done too early, and for a
> restart we do not wait for all the windows being restored. Instead we run
> the tests right after `sessionrestore-windows-restored` has been fired.
> 
> Mike, this is a high frequent failure. Maybe you could tell us if there is
> another event we have to wait for before continuing the test after a restart?

Well, for individual windows, you can use the following:

```js
function promiseWindowRestored(window) {
  return new Promise(resolve => window.addEventListener("SSWindowRestored", resolve, {once: true}));
}
```

... which uses the 'SSWindowRestored' event.

This might prove more reliable.
Flags: needinfo?(mdeboer)
I see. And when we are too late and the even has already been fired? Is there a property on the window object which tells us that it has finished restoring?
Flags: needinfo?(mdeboer)
Unfortunately, no. There's no such property at the moment. That doesn't mean it's not something I'd like to have; please feel free to add it if you think that's what's needed here.
Flags: needinfo?(mdeboer)
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → INCOMPLETE
This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#?job_id=203917476&repo=try&lineNumber=48471

13:13:37     INFO -  1538918017439	Marionette	TRACE	3 -> [0,80,"WebDriver:GetPageSource",{}]
13:13:37     INFO -  1538918017443	Marionette	TRACE	3 <- [1,80,null,{"value":"<html dir=\"ltr\" lang=\"en-US\"><head>\n    <meta charset=\"utf-8\">\n    <meta http-equiv=\"Content-Se ... ose-btn\" title=\"Close\"></button></div></div><div id=\"asr-newtab-container\" style=\"z-index: 1;\"></div></body></html>"}]
13:13:37     INFO -  1538918017447	Marionette	TRACE	3 -> [0,81,"Marionette:SetContext",{"value":"chrome"}]
13:13:37     INFO -  1538918017447	Marionette	TRACE	3 <- [1,81,null,{"value":null}]
13:13:37     INFO - TEST-UNEXPECTED-FAIL | testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | AssertionError: Non private browsing windows should have
13:13:37     INFO -                          been restored. Expected set([('http://127.0.0.1:53565/layout/mozilla_organizations.html', 'http://127.0.0.1:53565/layout/mozilla_community.html'), ('http://127.0.0.1:53565/layout/mozilla.html',), ('http://127.0.0.1:53565/layout/mozilla_governance.html', 'http://127.0.0.1:53565/layout/mozilla_grants.html')]), got set([(u'about:home',)]).
13:13:37     INFO - Traceback (most recent call last):
13:13:37     INFO -   File "Z:\task_1538916945\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 159, in run
13:13:37     INFO -     testMethod()
13:13:37     INFO -   File "Z:\task_1538916945\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py", line 82, in test_restore_with_restart
13:13:37     INFO -     """.format(self.test_windows, current_windows_set))
13:13:37     INFO - TEST-INFO took 11146ms
13:13:37     INFO -  1538918017467	Marionette	TRACE	3 -> [0,82,"Marionette:GetContext",{}]
13:13:37     INFO -  1538918017467	Marionette	TRACE	3 <- [1,82,null,{"value":"chrome"}]
13:13:37     INFO -  1538918017468	Marionette	TRACE	3 -> [0,83,"WebDriver:DeleteSession",{}]
13:13:37     INFO -  1538918017469	Marionette	TRACE	3 <- [1,83,null,{"value":null}]
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
As it looks like the session isn't restored at all when I check the assertion details from comment 48:

13:13:37     INFO -                          been restored. Expected set([('http://127.0.0.1:53565/layout/mozilla_organizations.html', 'http://127.0.0.1:53565/layout/mozilla_community.html'), ('http://127.0.0.1:53565/layout/mozilla.html',), ('http://127.0.0.1:53565/layout/mozilla_governance.html', 'http://127.0.0.1:53565/layout/mozilla_grants.html')]), got set([(u'about:home',)]).

Maybe this is a new race condition which has been caused by the recent merge from mozilla-central to mozilla-beta.

I would propose that we add a `Wait.until()` call for the assertion with a timeout of 5s, which should be enough.
Assignee: nobody → hskupin
Status: REOPENED → ASSIGNED
Priority: P5 → P1
This bug exists longer as the regression on bug 1496759. But it might have been a rare race condition before, which now is triggered way easier than before. The reason for the failure is basically the following commit:

https://hg.mozilla.org/integration/autoland/rev/8793e332890e

I will have to investigate it a bit more tomorrow, and also check if landing the patch on bug 1438009 will somewhat help here too.
We can close this bug again as incomplete once the backout/skip patch on bug 1493796 landed. It is just a temporary issue, and not related to the original one as filed about a year ago.
Assignee: hskupin → nobody
Status: ASSIGNED → NEW
Depends on: 1493796
Priority: P1 → P5
As mentioned in my last comment the failure disappeared again. I was not able to identify the root cause of it, as such closing as incomplete again.
Status: NEW → RESOLVED
Closed: Last year11 months ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=210303941&repo=mozilla-inbound&lineNumber=49253
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.