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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: cbook [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=118423556&repo=mozilla-central

https://queue.taskcluster.net/v1/task/DZ6k62p8TaSKQSUL2Jqa4Q/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

21 failures in 1008 pushes (0.021 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 9
* mozilla-central: 6
* mozilla-inbound: 5
* try: 1

Platform breakdown:
* linux64: 14
* linux32: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-07-24&endday=2017-07-30&tree=all

Comment 2

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

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')

Comment 3

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

Attachment: screenshot.png

Comment 4

[Erica Wright [: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.

Comment 5

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

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?

Comment 6

[Andreas Tolfsen ❲: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.

Comment 7

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

So it means none of the latest patches as landed in the last days which covered window resizing fixed that yet?

Comment 8

[Andreas Tolfsen ❲: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.

Comment 9

[Intermittent Failures Robot]

4 failures in 1032 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 4

Platform breakdown:
* linux32-nightly: 3
* linux64-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-09-11&endday=2017-09-17&tree=all

Comment 10

[Intermittent Failures Robot]

1 failures in 943 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-09-18&endday=2017-09-24&tree=all

Comment 11

[Intermittent Failures Robot]

1 failures in 947 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 12

[Intermittent Failures Robot]

21 failures in 116 pushes (0.181 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 21

Platform breakdown:
* linux64: 9
* linux32: 5
* windows7-32: 4
* windows10-64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-11-03&endday=2017-11-03&tree=all

Comment 13

[Dorel Luca [:dluca]]

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?

Comment 14

[Geoff Brown [:gbrown]]

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.

Comment 15

[Intermittent Failures Robot]

34 failures in 857 pushes (0.04 failures/push) were associated with this bug in the last 7 days.   

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* autoland: 34

Platform breakdown:
* linux64: 13
* windows7-32: 8
* windows10-64: 7
* linux32: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 16

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

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.

Comment 17

[Andreea Pavel [:apavel]]

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,{}]

Comment 18

[Intermittent Failures Robot]

1 failures in 657 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2018-01-15&endday=2018-01-21&tree=all

Comment 19

[Intermittent Failures Robot]

1 failures in 735 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1384875&startday=2018-01-29&endday=2018-02-04&tree=all

Comment 20

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 21

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

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