Closed Bug 1384875 Opened 5 years ago Closed 4 years ago

Intermittent test_tabbar_session_restore_button.py TestTabbarSessionRestoreButton.test_window_resizing | AssertionError: u'visible' != 'hidden'

Categories

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

Version 3
defect

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Assigned: dao)

References

Details

(Keywords: bulk-close-intermittents, intermittent-failure, Whiteboard: [stockwell fixed:backout])

Attachments

(1 file)

This started July 27th. Erica, do you know if something has been changed for the button at this time? It's visible when it should be hidden. Maybe it's related to the window size?

[task 2017-07-27T09:35:49.103230Z] 09:35:49     INFO - TEST-UNEXPECTED-FAIL | test_tabbar_session_restore_button.py TestTabbarSessionRestoreButton.test_window_resizing | AssertionError: u'visible' != 'hidden'
[task 2017-07-27T09:35:49.104485Z] 09:35:49     INFO - Traceback (most recent call last):
[task 2017-07-27T09:35:49.108787Z] 09:35:49     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 156, in run
[task 2017-07-27T09:35:49.108847Z] 09:35:49     INFO -     testMethod()
[task 2017-07-27T09:35:49.109270Z] 09:35:49     INFO -   File "/home/worker/workspace/build/tests/firefox-ui/tests/functional/sessionstore/test_tabbar_session_restore_button.py", line 77, in test_window_resizing
[task 2017-07-27T09:35:49.109346Z] 09:35:49     INFO -     self.assertEqual(wrapper.value_of_css_property('visibility'), 'hidden')
Flags: needinfo?(ewright)
Nothing has been changed for the button. It could be window size, if the window does not successfully resize small then the button will show.
Flags: needinfo?(ewright)
Hm, so the failing lines are:

>        self.marionette.set_window_size(335, 335)
>        self.assertEqual(wrapper.value_of_css_property('visibility'), 'hidden')

Given the screenshot for this failure the window is of size 1200 x 1200 and not 335 x 335.

Andreas, is that another instance of a race condition when we return to early from set window size? Will it be fixed by one of your patches?
Flags: needinfo?(ato)
(In reply to Henrik Skupin (:whimboo) from comment #5)

> Hm, so the failing lines are:
> 
> >        self.marionette.set_window_size(335, 335)
> >        self.assertEqual(wrapper.value_of_css_property('visibility'), 'hidden')
> 
> Given the screenshot for this failure the window is of size 1200 x
> 1200 and not 335 x 335.
> 
> Andreas, is that another instance of a race condition when we
> return to early from set window size? Will it be fixed by one of
> your patches?

I think that’s a reasonable assumption considering it only fails
on Linux, where we now window resizing happens asynchronously.

Despite all the changes I have made to increase the determinism
of WebDriver:SetWindowRect, the core of the problem here is that
we can’t rely on window.{outerWidth,outerHeight} when polling
for the window’s size to have changed.  These two DOM properties
are populated with the new size before the resize transition has
completed.

As you can tell from
https://searchfox.org/mozilla-central/rev/f0e4ae5f8c40ba742214e89aba3f554da0b89a33/testing/marionette/driver.js#1345-1457,
we have put into place a large number of guards to prevent this:
it first waits for the "resize" DOM event to fire, then throttles
the event by requesting an animation frame after the main thread is
idle.  Then as a last safeguard it poll-waits for the window’s
size to have changed from its original dimensions.

Unfortunately, I don’t have any more good ideas for how to make
this more reliable.  I should add that this is also an unsolved
problem in GTK and internally in mochitests for window.resizeTo.
Flags: needinfo?(ato)
So it means none of the latest patches as landed in the last days which covered window resizing fixed that yet?
Flags: needinfo?(ato)
(In reply to Henrik Skupin (:whimboo) from comment #7)
> So it means none of the latest patches as landed in the last days which
> covered window resizing fixed that yet?

Apparently not.

I would like to see how this intermittent evolves over the next week or so.
Flags: needinfo?(ato)
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
This bug failed 35 times in the last 7 days. Most than half of the fails are happening on Linux, the rest on Windows. The build types are asan, debug, opt and pgo.

Here is a recent log:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=142005695&lineNumber=44659

And here is a part of the log:

[task 2017-11-03T17:41:30.266Z] 17:41:30     INFO -  1509730890258	Marionette	TRACE	1 <- [1,47,null,{}]
[task 2017-11-03T17:41:30.267Z] 17:41:30     INFO -  1509730890260	Marionette	TRACE	1 -> [0,48,"takeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2017-11-03T17:41:30.326Z] 17:41:30     INFO -  1509730890319	Marionette	TRACE	1 <- [1,48,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABLAAAASwCAYAAADrIbPPAAAgAElEQVR4nOzdy29c54HmYS8b6P8jQBpo9M6zmAF600tvG7PshSEu1bMJtHSAWXmX7hkDI/fCgAQYi ... AAABgTWABAAAAsCawAAAAAFgTWAAAAACsCSwAAAAA1gQWAAAAAGsCCwAAAIA1gQUAAADAmsACAAAAYE1gAQAAALAmsAAAAABYC3l3cyVvUe7QAAAAAElFTkSuQmCC"}]
[task 2017-11-03T17:41:30.342Z] 17:41:30     INFO -  1509730890331	Marionette	TRACE	1 -> [0,49,"setContext",{"value":"chrome"}]
[task 2017-11-03T17:41:30.343Z] 17:41:30     INFO -  1509730890332	Marionette	TRACE	1 <- [1,49,null,{}]
[task 2017-11-03T17:41:30.344Z] 17:41:30     INFO -  1509730890333	Marionette	TRACE	1 -> [0,50,"getContext",{}]
[task 2017-11-03T17:41:30.344Z] 17:41:30     INFO -  1509730890333	Marionette	TRACE	1 <- [1,50,null,{"value":"chrome"}]
[task 2017-11-03T17:41:30.345Z] 17:41:30     INFO -  1509730890334	Marionette	TRACE	1 -> [0,51,"setContext",{"value":"content"}]
[task 2017-11-03T17:41:30.346Z] 17:41:30     INFO -  1509730890334	Marionette	TRACE	1 <- [1,51,null,{}]
[task 2017-11-03T17:41:30.347Z] 17:41:30     INFO -  1509730890335	Marionette	TRACE	1 -> [0,52,"getPageSource",{}]
[task 2017-11-03T17:41:30.357Z] 17:41:30     INFO - TEST-UNEXPECTED-FAIL | test_tabbar_session_restore_button.py TestTabbarSessionRestoreButton.test_window_resizing | AssertionError: u'hidden' != 'visible'
[task 2017-11-03T17:41:30.357Z] 17:41:30     INFO - Traceback (most recent call last):
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 156, in run
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO -     testMethod()
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO -   File "/builds/worker/workspace/build/tests/firefox-ui/tests/functional/sessionstore/test_tabbar_session_restore_button.py", line 73, in test_window_resizing
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO -     self.assertEqual(wrapper.value_of_css_property('visibility'), 'visible')
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO - TEST-INFO took 9142ms
[task 2017-11-03T17:41:30.358Z] 17:41:30     INFO -  1509730890339	Marionette	TRACE	1 <- [1,52,null,{"value":"<html><head></head><body></body></html>"}]
[task 2017-11-03T17:41:30.359Z] 17:41:30     INFO -  1509730890339	Marionette	TRACE	1 -> [0,53,"setContext",{"value":"chrome"}]
[task 2017-11-03T17:41:30.359Z] 17:41:30     INFO -  1509730890340	Marionette	TRACE	1 <- [1,53,null,{}]
[task 2017-11-03T17:41:30.360Z] 17:41:30     INFO -  1509730890348	Marionette	TRACE	1 -> [0,54,"getContext",{}]
[task 2017-11-03T17:41:30.361Z] 17:41:30     INFO -  1509730890348	Marionette	TRACE	1 <- [1,54,null,{"value":"chrome"}]
[task 2017-11-03T17:41:30.361Z] 17:41:30     INFO -  1509730890350	Marionette	TRACE	1 -> [0,55,"deleteSession",{}]
[task 2017-11-03T17:41:30.362Z] 17:41:30     INFO -  1509730890353	Marionette	TRACE	1 <- [1,55,null,{}]

:gbrown: Hi, can you please take a look at this bug?
Flags: needinfo?(gbrown)
Whiteboard: [stockwell needswork]
It looks like this sudden spike started with the change from bug 1414252. 

https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=firefox-ui&tochange=bedc52fb5267646d5689e4450a455daf66e8e2ac&fromchange=4635df9d3bb6919a7480cdd41cb8c4af5e2d4e71

That change was backed out and the test is no longer failing.
Flags: needinfo?(gbrown)
See Also: → 1414252
Whiteboard: [stockwell needswork] → [stockwell fixed:backout]
There was a single failure about 25 days ago. Since then it didn't happen anymore beside the issue and backout mentioned above. Lets close as WFM.
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → VERIFIED
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=157630039&repo=autoland&lineNumber=44102

[task 2018-01-21T16:09:37.028Z] 16:09:37     INFO -  1516550977025	Marionette	TRACE	1 <- [1,40,null,{}]
[task 2018-01-21T16:09:37.030Z] 16:09:37     INFO -  1516550977026	Marionette	TRACE	1 -> [0,41,"findElement",{"using":"css selector","value":":root"}]
[task 2018-01-21T16:09:37.032Z] 16:09:37     INFO -  1516550977029	Marionette	TRACE	1 <- [1,41,null,{"value":{"chromeelement-9fc5-4b51-a3c8-01716eedeb04":"a1f2616a-a592-413f-ab7e-ab8967a4b34b","ELEMENT":"a1f2616a-a592-413f-ab7e-ab8967a4b34b"}}]
[task 2018-01-21T16:09:37.033Z] 16:09:37     INFO -  1516550977031	Marionette	TRACE	1 -> [0,42,"findElement",{"using":"id","value":"tabbrowser-tabs","element":"a1f2616a-a592-413f-ab7e-ab8967a4b34b"}]
[task 2018-01-21T16:09:37.041Z] 16:09:37     INFO -  1516550977036	Marionette	TRACE	1 <- [1,42,null,{"value":{"chromeelement-9fc5-4b51-a3c8-01716eedeb04":"75ced88e-242c-4ef6-836b-ca4a4014c008","ELEMENT":"75ced88e-242c-4ef6-836b-ca4a4014c008"}}]
[task 2018-01-21T16:09:37.042Z] 16:09:37     INFO -  1516550977037	Marionette	TRACE	1 -> [0,43,"findElement",{"using":"anon attribute","value":{"anonid":"restore-tabs-button-wrapper"},"element":"75ced88e-242c-4ef6-836b-ca4a4014c008"}]
[task 2018-01-21T16:09:37.043Z] 16:09:37     INFO -  1516550977039	Marionette	TRACE	1 <- [1,43,null,{"value":{"chromeelement-9fc5-4b51-a3c8-01716eedeb04":"ab11f65d-2442-41ac-8d92-c25ffa6aa421","ELEMENT":"ab11f65d-2442-41ac-8d92-c25ffa6aa421"}}]
[task 2018-01-21T16:09:37.043Z] 16:09:37     INFO -  1516550977040	Marionette	TRACE	1 -> [0,44,"setWindowSize",{"width":1200,"height":1200}]
[task 2018-01-21T16:09:37.083Z] 16:09:37     INFO -  1516550977077	Marionette	TRACE	1 <- [1,44,null,{"x":0,"y":0,"width":1200,"height":1200,"state":"normal"}]
[task 2018-01-21T16:09:37.083Z] 16:09:37     INFO -  1516550977080	Marionette	TRACE	1 -> [0,45,"getElementValueOfCssProperty",{"propertyName":"visibility","id":"ab11f65d-2442-41ac-8d92-c25ffa6aa421"}]
[task 2018-01-21T16:09:37.091Z] 16:09:37     INFO -  1516550977085	Marionette	TRACE	1 <- [1,45,null,{"value":"visible"}]
[task 2018-01-21T16:09:37.092Z] 16:09:37     INFO -  1516550977086	Marionette	TRACE	1 -> [0,46,"setWindowSize",{"width":335,"height":335}]
[task 2018-01-21T16:09:37.198Z] 16:09:37     INFO -  1516550977194	Marionette	TRACE	1 <- [1,46,null,{"x":0,"y":0,"width":335,"height":335,"state":"normal"}]
[task 2018-01-21T16:09:37.200Z] 16:09:37     INFO -  1516550977196	Marionette	TRACE	1 -> [0,47,"getElementValueOfCssProperty",{"propertyName":"visibility","id":"ab11f65d-2442-41ac-8d92-c25ffa6aa421"}]
[task 2018-01-21T16:09:37.202Z] 16:09:37     INFO -  1516550977197	Marionette	TRACE	1 <- [1,47,null,{"value":"visible"}]
[task 2018-01-21T16:09:37.217Z] 16:09:37     INFO -  1516550977207	Marionette	TRACE	1 -> [0,48,"getContext",{}]
[task 2018-01-21T16:09:37.218Z] 16:09:37     INFO -  1516550977207	Marionette	TRACE	1 <- [1,48,null,{"value":"chrome"}]
[task 2018-01-21T16:09:37.219Z] 16:09:37     INFO -  1516550977212	Marionette	TRACE	1 -> [0,49,"setContext",{"value":"chrome"}]
[task 2018-01-21T16:09:37.219Z] 16:09:37     INFO -  1516550977212	Marionette	TRACE	1 <- [1,49,null,{}]
[task 2018-01-21T16:09:37.220Z] 16:09:37     INFO -  1516550977213	Marionette	TRACE	1 -> [0,50,"takeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2018-01-21T16:09:37.237Z] 16:09:37     INFO -  1516550977230	Marionette	TRACE	1 <- [1,50,null,{"value":"iVBORw0KGgoAAAANSUhEUgAAAU8AAAFPCAYAAADNzUzyAAAPoUlEQVR4nO3dvW8c953AYZUB8n8YcIAgna64A9KkdBtcmUKw/gPXMnBN ... dAgHgCBIgnQIB4AgSIJ0CAeAIEiCdAgHgCBIgnQIB4AgSIJ0CAeAIEiCdAgHgCBIgnQIB4AgSIJ0CAeAIEiCdAgHgCBPw/L3L3rkQ1rXAAAAAASUVORK5CYII="}]
[task 2018-01-21T16:09:37.238Z] 16:09:37     INFO -  1516550977232	Marionette	TRACE	1 -> [0,51,"setContext",{"value":"chrome"}]
[task 2018-01-21T16:09:37.238Z] 16:09:37     INFO -  1516550977232	Marionette	TRACE	1 <- [1,51,null,{}]
[task 2018-01-21T16:09:37.239Z] 16:09:37     INFO -  1516550977233	Marionette	TRACE	1 -> [0,52,"getContext",{}]
[task 2018-01-21T16:09:37.240Z] 16:09:37     INFO -  1516550977233	Marionette	TRACE	1 <- [1,52,null,{"value":"chrome"}]
[task 2018-01-21T16:09:37.241Z] 16:09:37     INFO -  1516550977234	Marionette	TRACE	1 -> [0,53,"setContext",{"value":"content"}]
[task 2018-01-21T16:09:37.241Z] 16:09:37     INFO -  1516550977235	Marionette	TRACE	1 <- [1,53,null,{}]
[task 2018-01-21T16:09:37.242Z] 16:09:37     INFO -  1516550977235	Marionette	TRACE	1 -> [0,54,"getPageSource",{}]
[task 2018-01-21T16:09:37.259Z] 16:09:37     INFO - TEST-UNEXPECTED-FAIL | testing/firefox-ui/tests/functional/sessionstore/test_tabbar_session_restore_button.py TestTabbarSessionRestoreButton.test_window_resizing | AssertionError: u'visible' != 'hidden'
[task 2018-01-21T16:09:37.260Z] 16:09:37     INFO - Traceback (most recent call last):
[task 2018-01-21T16:09:37.261Z] 16:09:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-01-21T16:09:37.262Z] 16:09:37     INFO -     testMethod()
[task 2018-01-21T16:09:37.262Z] 16:09:37     INFO -   File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/test_tabbar_session_restore_button.py", line 77, in test_window_resizing
[task 2018-01-21T16:09:37.263Z] 16:09:37     INFO -     self.assertEqual(wrapper.value_of_css_property('visibility'), 'hidden')
[task 2018-01-21T16:09:37.263Z] 16:09:37     INFO - TEST-INFO took 9921ms
[task 2018-01-21T16:09:37.264Z] 16:09:37     INFO -  1516550977245	Marionette	TRACE	1 <- [1,54,null,{"value":"<html><head></head><body></body></html>"}]
[task 2018-01-21T16:09:37.264Z] 16:09:37     INFO -  1516550977246	Marionette	TRACE	1 -> [0,55,"setContext",{"value":"chrome"}]
[task 2018-01-21T16:09:37.265Z] 16:09:37     INFO -  1516550977247	Marionette	TRACE	1 <- [1,55,null,{}]
[task 2018-01-21T16:09:37.266Z] 16:09:37     INFO -  1516550977250	Marionette	TRACE	1 -> [0,56,"getContext",{}]
[task 2018-01-21T16:09:37.267Z] 16:09:37     INFO -  1516550977251	Marionette	TRACE	1 <- [1,56,null,{"value":"chrome"}]
[task 2018-01-21T16:09:37.267Z] 16:09:37     INFO -  1516550977253	Marionette	TRACE	1 -> [0,57,"deleteSession",{}]
[task 2018-01-21T16:09:37.268Z] 16:09:37     INFO -  1516550977254	Marionette	TRACE	1 <- [1,57,null,{}]
Status: VERIFIED → REOPENED
Resolution: WORKSFORME → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE

(In reply to Geoff Brown [:gbrown] from comment #14)

It looks like this sudden spike started with the change from bug 1414252.

https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=firefox-
ui&tochange=bedc52fb5267646d5689e4450a455daf66e8e2ac&fromchange=4635df9d3bb69
19a7480cdd41cb8c4af5e2d4e71

That change was backed out and the test is no longer failing.

We should have closed this bug as fixed then. Doing it now.

Assignee: nobody → dao+bmo
Resolution: INCOMPLETE → FIXED
You need to log in before you can comment on or make changes to this bug.