1360446 - Intermittent test_click.py TestLegacyClick.test_click | TimeoutException: Timeout loading page after 300000ms

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: hskupin [at] mozilla.com

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

https://archive.mozilla.org/pub/firefox/tinderbox-builds/autoland-win64-debug/1493349925/autoland_win8_64-debug_test-marionette-e10s-bm110-tests1-windows-build512.txt.gz

We timeout for a get request:

1493354027007	Marionette	TRACE	449 -> [0,2,"get",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cbutton%3Eclick%20me%3C/button%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20window.clicks%20%3D%200%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20let%20button%20%3D%20document.querySelector%28%22button%22%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20button.addEventListener%28%22click%22%2C%20%28%29%20%3D%3E%20window.clicks%2B%2B%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20"}]
1493354027074	Marionette	DEBUG	Received DOM event "pagehide" for "about:robots"
1493354027075	Marionette	DEBUG	Received DOM event "unload" for "about:robots"
[1464] WARNING: '!compMgr', file c:/builds/moz2_slave/autoland-w64-d-000000000000000/build/src/xpcom/components/nsComponentManagerUtils.cpp, line 63
[Child 1464] WARNING: '!compMgr', file c:/builds/moz2_slave/autoland-w64-d-000000000000000/build/src/xpcom/components/nsComponentManagerUtils.cpp, line 63
1493354027135	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "30"
++DOCSHELL 000000D67621C800 == 1 [pid = 1464] [id = {401630ee-9cf0-44ec-922f-214e9f79f610}]
++DOMWINDOW == 1 (000000D67621D000) [pid = 1464] [serial = 1] [outer = 0000000000000000]
++DOMWINDOW == 2 (000000D67CA0A000) [pid = 1464] [serial = 2] [outer = 000000D67621D000]
1493354027595	Marionette	DEBUG	loaded listener.js

Given that we haven't seen this before it might be related to bug 1335778.

Comment 1

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

Please note the additional received observer notification, which was caused by an upcoming remoteness change. So it should clearly be related to bug 1335778 then because the observer code has been added there.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1

Platform breakdown:
* windows7-32-vm: 2
* osx-10-10: 2
* windows8-64: 1

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

Comment 3

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

All the failures happened on April 28th only, the day of landing the click+page load patch. I will have another look at this bug if there are more occurrences in the future.

Comment 4

[Intermittent Failures Robot]

9 failures in 770 pushes (0.012 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 5
* autoland: 3
* mozilla-central: 1

Platform breakdown:
* osx-10-10: 5
* windows8-64: 2
* windows7-32-vm: 1
* linux32: 1

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

Comment 5

[Intermittent Failures Robot]

7 failures in 891 pushes (0.008 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 3
* autoland: 3
* mozilla-central: 1

Platform breakdown:
* osx-10-10: 4
* windows7-32-vm: 1
* windows10-64-vm: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1360446&startday=2017-05-22&endday=2017-05-28&tree=all

Comment 6

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

With bug 1223277 we will have some improvements regarding window/tab closing. Lets see if it makes some differences.

Comment 7

[Intermittent Failures Robot]

15 failures in 820 pushes (0.018 failures/push) were associated with this bug in the last 7 days.   

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

Platform breakdown:
* windows7-32-vm: 7
* osx-10-10: 5
* linux32: 2
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1360446&startday=2017-05-29&endday=2017-06-04&tree=all

Comment 8

[Intermittent Failures Robot]

14 failures in 864 pushes (0.016 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 9
* autoland: 5

Platform breakdown:
* windows7-32-vm: 5
* linux32: 4
* osx-10-10: 3
* linux64: 2

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

Comment 9

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

The timeout here seems to be in `get` and specifically when loading the data URL:

1497006383667	Marionette	TRACE	430 -> [0,2,"get",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cbutton%3Eclick%20me%3C/button%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20window.clicks%20%3D%200%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20let%20button%20%3D%20document.querySelector%28%22button%22%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20button.addEventListener%28%22click%22%2C%20%28%29%20%3D%3E%20window.clicks%2B%2B%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%20%20%20%20"}]
1497006383670	Marionette	DEBUG	Received DOM event "beforeunload" for "about:robots"
[Child 1968] WARNING: '!mMainThread', file /home/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 330
[Child 1968] WARNING: '!mMainThread', file /home/worker/workspace/build/src/xpcom/threads/nsThreadManager.cpp, line 330
--DOCSHELL 0x11b584800 == 2 [pid = 1968] [id = {231305ae-316a-b14f-a386-09959cd627be}]
--DOCSHELL 0x11b58b800 == 1 [pid = 1968] [id = {fe6ea7e4-cec4-ff42-8396-77651b46ecb3}]
--DOCSHELL 0x1140f1000 == 0 [pid = 1968] [id = {3f96298a-3810-de40-8282-c035b564a282}]
1497006383777	Marionette	DEBUG	Received DOM event "pagehide" for "about:robots"
1497006383777	Marionette	DEBUG	Received DOM event "unload" for "about:robots"
++DOCSHELL 0x11bd66000 == 1 [pid = 1969] [id = {637d8ea9-07ed-ca4c-ac47-3c8f416bc7d7}]
++DOMWINDOW == 1 (0x11bd66800) [pid = 1969] [serial = 1] [outer = 0x0]
1497006383807	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "23"
++DOMWINDOW == 2 (0x12586c800) [pid = 1969] [serial = 2] [outer = 0x11bd66800]
1497006383997	Marionette	DEBUG	loaded listener.js
[..]
1497006684772	Marionette	TRACE	430 <- [1,2,{"error":"timeout","message":"Timeout loading page after 300000ms","stacktrace":"WebDriverError@chrome://marionette/content/error.js:222:5\nTimeoutError@chrome://marionette/content/error.js:472:5\nnotify@chrome://marionette/content/listener.js:296:17\n"},null]

It means right after triggering the page load the framescript gets reloaded. Then no single load event is taking place.

I assume this is related to bug 1368434.

Comment 10

[Intermittent Failures Robot]

18 failures in 147 pushes (0.122 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 10
* autoland: 4
* try: 3
* mozilla-central: 1

Platform breakdown:
* linux64: 8
* windows7-32-vm: 5
* linux32: 3
* windows8-64: 2

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

Comment 11

[Joel Maher ( :jmaher ) (UTC -8)]

this intermittent failure has 50 instances in the last week almost all on debug.

:whimboo, I see you have a possible root cause, but that bug has no progress in almost 3 weeks- can you take a look at this bug in the next week and see if we can get a fix or consider disabling the test?

Comment 12

[Intermittent Failures Robot]

50 failures in 814 pushes (0.061 failures/push) were associated with this bug in the last 7 days. 

This is the #38 most frequent failure this week.  

** 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:
* mozilla-inbound: 24
* autoland: 13
* mozilla-central: 7
* try: 5
* mozilla-beta: 1

Platform breakdown:
* linux64: 19
* linux32: 14
* windows7-32-vm: 9
* windows8-64: 5
* osx-10-10: 2
* linux64-ccov: 1

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

Comment 13

[Intermittent Failures Robot]

16 failures in 151 pushes (0.106 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 10
* mozilla-inbound: 4
* try: 2

Platform breakdown:
* linux32: 9
* windows8-64: 2
* windows7-32-vm: 2
* linux64: 2
* windows10-64-vm: 1

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

Comment 14

[Intermittent Failures Robot]

24 failures in 173 pushes (0.139 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 14
* mozilla-inbound: 5
* try: 3
* mozilla-central: 2

Platform breakdown:
* linux32: 11
* windows7-32-vm: 5
* linux64: 4
* windows8-64: 2
* windows10-64-vm: 1
* linux64-ccov: 1

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

Comment 15

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: temporarily disable test_click.py to reduce the failures

Given the failure rate and higher priority items to work on this week than fixing this test, lets disable for now:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7544bf58474a00e373647b04e96ffbce0aca9bc8

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fcc60b7fa3ef
Intermittent test_click.py TestLegacyClick.test_click. temporarily disable on debug+e10s. r=gbrown

Comment 17

[Andreas Tolfsen ❲:ato❳]

We need to run this test on e10s with Marionette.  whimboo, do you have
capacity to look into it?

Comment 18

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

This is not happening on OS X so I cannot reproduce it. But please see the dependency list. I think it is related to bug 1368434, and I can reproduce such an issue via the failure on bug 1353599. This means we need bug 1368434 fixed.

Comment 19

[Intermittent Failures Robot]

23 failures in 170 pushes (0.135 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 15
* mozilla-inbound: 5
* mozilla-central: 3

Platform breakdown:
* windows7-32-vm: 6
* linux64: 6
* linux32: 5
* windows8-64: 3
* osx-10-10: 2
* windows10-64-vm: 1

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

Comment 20

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/fcc60b7fa3ef

Comment 21

[Intermittent Failures Robot]

68 failures in 892 pushes (0.076 failures/push) were associated with this bug in the last 7 days. 

This is the #27 most frequent failure this week.  

** 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: 40
* mozilla-inbound: 15
* mozilla-central: 7
* try: 6

Platform breakdown:
* linux32: 24
* windows7-32-vm: 16
* linux64: 10
* windows8-64: 7
* osx-10-10: 5
* windows10-64-vm: 3
* linux64-ccov: 2
* macosx64-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1360446&startday=2017-06-19&endday=2017-06-25&tree=all

Comment 22

[Intermittent Failures Robot]

14 failures in 718 pushes (0.019 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 7
* mozilla-inbound: 5
* mozilla-central: 2

Platform breakdown:
* osx-10-10: 9
* linux32: 4
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1360446&startday=2017-06-26&endday=2017-07-02&tree=all

Comment 23

[Intermittent Failures Robot]

23 failures in 656 pushes (0.035 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 12
* autoland: 8
* mozilla-beta: 3

Platform breakdown:
* osx-cross: 9
* osx-10-10: 6
* linux32: 4
* windows8-64: 3
* linux64: 1

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

Comment 24

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

Joel, your skip patch was for debug and e10s only. But it looks like that opt builds are failing too very often now. Maybe we have to skip more broader.

Comment 25

[Geoff Brown [:gbrown]]

Attachment: skip on all e10s

I totally agree. How about this?

Comment 26

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

Comment on attachment 8885282 [details] [diff] [review]
skip on all e10s

Looks good. Thanks.

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c22ccebf80cd
Broaden skip of test_click.py TestLegacyClick.test_click for continued intermittent failures; r=whimboo

Comment 28

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c22ccebf80cd

Comment 29

[Intermittent Failures Robot]

7 failures in 720 pushes (0.01 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1
* mozilla-central: 1
* mozilla-beta: 1

Platform breakdown:
* osx-cross: 3
* linux32: 3
* linux64: 1

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

Comment 30

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

(In reply to Geoff Brown [:gbrown] from comment #25)
> Created attachment 8885282 [details] [diff] [review]
> skip on all e10s
> 
> I totally agree. How about this?

Geoff, I actually didn't really notice that we skip ALL click tests while this is a failure only for a single test inside this file. We should really revert that and only skip the failing test. Can you work on that? Sorry, that this slipped through but it is major now. Thanks.

Comment 31

[Geoff Brown [:gbrown]]

Attachment: skip only TestLegacyClick.test_click, only on e10s

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e4242ef09010ff9d8263776ffb37e76b401d523c

Comment 32

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

Comment on attachment 8887230 [details] [diff] [review]
skip only TestLegacyClick.test_click, only on e10s

r=me with a green try push. Thanks a lot!

Comment 33

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e3dcb77ea22f
Enable marionette test_click.py, but disable the troublesome TestLegacyClick.test_click part, on e10s; r=whimboo

Comment 34

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e3dcb77ea22f

Comment 35

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/d4c3c0d298ab

Comment 36

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 37

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

Fixed by my patch on bug 1368434.

Comment 38

[Firefox Bug Husbandry Bot]

Removing leave-open keyword from resolved bugs, per :sylvestre.

Comment 39

[BMO Automation]

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