Closed Bug 1394351 Opened 2 years ago Closed Last year

WebDriver:ElementClick returns too early when current tab gets closed

Categories

(Testing :: Marionette, defect, P3)

57 Branch
defect

Tracking

(firefox-esr60 fix-optional, firefox57 wontfix, firefox58 wontfix, firefox59 wontfix, firefox61 fixed, firefox62 fixed)

RESOLVED FIXED
mozilla62
Tracking Status
firefox-esr60 --- fix-optional
firefox57 --- wontfix
firefox58 --- wontfix
firefox59 --- wontfix
firefox61 --- fixed
firefox62 --- fixed

People

(Reporter: whimboo, Assigned: whimboo)

References

Details

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.
No longer blocks: 1383686
Priority: -- → P3
can we get this fixed?  It is blocking a couple high frequency intermittent bugs.
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?
Flags: needinfo?(hskupin)
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.
Flags: needinfo?(hskupin)
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.
Depends on: 1411393
Summary: Click command returns too early when current tab/window gets closed → Click command returns too early when current tab gets closed
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.
Depends on: 1414329
from bug 1383686, there were 47 failures in the last week- we are assuming fixing this will solve that bug.
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.
Summary: Click command returns too early when current tab gets closed → WebDriver:ElementClick returns too early when current tab gets closed
No longer blocks: 1383686
This race should have been fixed by my patch on bug 1452653.
Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: Last year
Depends on: 1452653
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
You need to log in before you can comment on or make changes to this bug.