1394351 - WebDriver:ElementClick returns too early when current tab gets closed

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P3)

Description

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

From bug 1383686:

> [task 2017-07-22T11:49:11.337803Z] 11:49:11     INFO -  1500724151332	Marionette	TRACE	408 -> [0,26,"switchToWindow",{"focus":true,"name":"2147483684"}]
> [task 2017-07-22T11:49:11.353788Z] 11:49:11     INFO -  1500724151345	Marionette	TRACE	408 <- [1,26,null,{}]

We switch to the active tab and load click.html...

> [task 2017-07-22T11:49:11.390108Z] 11:49:11     INFO -  1500724151378	Marionette	TRACE	408 -> [0,27,"get",{"url":"http://127.0.0.1:55848/clicks.html"}]
> [task 2017-07-22T11:49:11.813133Z] 11:49:11     INFO -  1500724151809	Marionette	DEBUG	Received DOM event "pageshow" for "http://127.0.0.1:55848/clicks.html"
> [task 2017-07-22T11:49:11.890109Z] 11:49:11     INFO -  1500724151881	Marionette	TRACE	408 <- [1,27,null,{}]

Then we click the close window link:

[task 2017-07-22T11:49:11.938462Z] 11:49:11     INFO -  1500724151932	Marionette	TRACE	408 -> [0,28,"findElement",{"using":"id","value":"close-window"}]
[task 2017-07-22T11:49:11.979179Z] 11:49:11     INFO -  1500724151965	Marionette	TRACE	408 <- [1,28,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"449d282d-92d3-4201-a7f4-155eda3d11ab","ELEMENT":"449d282d-92d3-4201-a7f4-155eda3d11ab"}}]
[task 2017-07-22T11:49:11.980651Z] 11:49:11     INFO -  [Parent 1106] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file /home/worker/workspace/build/src/netwerk/base/nsChannelClassifier.cpp, line 316
[task 2017-07-22T11:49:11.981328Z] 11:49:11     INFO -  1500724151971	Marionette	TRACE	408 -> [0,29,"clickElement",{"id":"449d282d-92d3-4201-a7f4-155eda3d11ab"}]
[task 2017-07-22T11:49:12.683597Z] 11:49:12     INFO -  1500724152678	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
[task 2017-07-22T11:49:12.685460Z] 11:49:12     INFO -  1500724152682	Marionette	TRACE	408 <- [1,29,null,{}]

Then the failure happens in tearDown and specifically in `close_all_tabs()`:

[task 2017-07-22T11:49:12.694112Z] 11:49:12     INFO -  1500724152688	Marionette	TRACE	408 -> [0,30,"getWindowHandles",{}]
[task 2017-07-22T11:49:12.695227Z] 11:49:12     INFO -  1500724152691	Marionette	TRACE	408 <- [1,30,null,["2147483649","2147483684"]]

We still get the window with the id `2147483684` reported. The next command (`switchToWindow`) fails because the window doesn't exist anymore. 

It means that:

1) clickElement returns too early when a tab gets closed, and it doesn't wait until it's completely gone

or

2) The window handles as returned by `getWindowHandles` are somehow cached. 

When the failure count increases I will have a look at this.

(In reply to Andreas Tolfsen ‹:ato› from comment #3)
> > 1) clickElement returns too early when a tab gets closed, and it
> > doesn't wait until it's completely gone
> 
> This seems like a reasonable explanation.  Window transitions on
> Linux, due to the nature of the X11 protocol, are asynchronous.  It
> is possible that waiting for the main thread to be idle would do the
> trick here.

Comment 1

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

can we get this fixed?  It is blocking a couple high frequency intermittent bugs.

Comment 2

[Henrietta Maior [:henrietta_maior]]

In the last 7 days, there have been 46 failures on the bugs which depend on this one.

:whimboo can you please take a look and provide an estimate on when this is going to be fixed?

Comment 3

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

Bug 1410366 has higher priority for me at the moment given that this affects various test jobs, and is not related to any test. Once that bug is fixed and the failures dropped I can start investigating this one.

Comment 4

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

This is actually only happening for closing a tab, but not when the window gets closed.

I just hit this failure on a Windows loaner. The following output shows the problem:

> 1509665035962	Marionette	TRACE	157 -> [0,23,"clickElement",{"id":"3223661e-c5a1-4179-901e-588425ab7140"}]
> 1509665036705	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
> 1509665036709	Marionette	TRACE	157 <- [1,23,null,{}]
> 1509665036717	Marionette	TRACE	157 -> [0,24,"getWindowHandles",{}]
> 1509665036721	Marionette	TRACE	157 <- [1,24,null,["4294967297","4294967332"]]

The output below actually shows how it has to look like:

> 1509696397244	Marionette	TRACE	3 -> [0,20,"clickElement",{"id":"2e93c50b-2719-2b49-b9f1-6edffc6f6cf3"}]
> 1509696397335	Marionette	DEBUG	Received DOM event "beforeunload" for "http://127.0.0.1:61517/clicks.html"
> 1509696397382	Marionette	DEBUG	Received DOM event TabClose for [object XULElement]
> 1509696397401	Marionette	TRACE	3 <- [1,20,null,{}]
> 1509696397403	Marionette	DEBUG	Received DOM event "pagehide" for "http://127.0.0.1:61517/clicks.html"
> 1509696397404	Marionette	DEBUG	Received DOM event "unload" for "http://127.0.0.1:61517/clicks.html"
> 1509696397407	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "2147483653"

As you can see, in the failing case we abort early because no page navigation has been detected, which means no `beforeunload` event has been received.

I have to make substantial changes in how we listen to `beforeunload` on bug 1411393. So maybe that will help here too.

Comment 5

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

As it looks like bug 1411393 hasn't had an influence here:

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

07:40:02     INFO -  1509982802586	Marionette	TRACE	162 -> [0,20,"clickElement",{"id":"ca3ef8c1-9f25-b94e-a761-aa443cb483da"}]
07:40:03     INFO -  1509982803189	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
07:40:03     INFO -  1509982803191	Marionette	TRACE	162 <- [1,20,null,{}]
07:40:03     INFO -  1509982803193	Marionette	TRACE	162 -> [0,21,"getWindowHandles",{}]
07:40:03     INFO -  1509982803194	Marionette	TRACE	162 <- [1,21,null,["2147483649","2147483686"]]

Here the listener got canceled after 600ms. By that time the tab should really have been closed.

I could imagine that the patch on bug 1414329 could make a difference here.

Comment 6

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

from bug 1383686, there were 47 failures in the last week- we are assuming fixing this will solve that bug.

Comment 7

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

So the extra delay we get from the changes on bug 1414329 is not enough. I still see this issue on autoland today:

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

[task 2017-11-15T09:04:07.336Z] 09:04:07     INFO -  1510736647331	Marionette	TRACE	171 -> [0,21,"clickElement",{"id":"503b2064-7432-443a-964c-043059f18dd8"}]
[task 2017-11-15T09:04:08.110Z] 09:04:08     INFO -  1510736648096	Marionette	DEBUG	Canceled page load listener because no navigation has been detected

Looks like I need a slower build maybe, but as bug 1417419 shows debug artifact builds only get the optimized variant. So I had to do a full debug non-optimized build locally.

Comment 8

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

This race should have been fixed by my patch on bug 1452653.