Closed Bug 1383686 Opened 7 years ago Closed 6 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Browsing context has been discarded

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Platform:
x86_64
Linux
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown]) 

> [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.
status-firefox55: --- → unaffected
status-firefox56: --- → affected
OS: Unspecified → Linux
(In reply to Henrik Skupin (:whimboo) from comment #2)

> 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.
See Also: → 1389601
Depends on: 1394351
A fix will be worked on bug 1394351.
No longer depends on: 1394351
See Also: 1389601 → 
this failure has increased in frequency in the last week or so, all debug failures, primarily on linux.

here is a log file:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=133235693&lineNumber=5388

and what looks to be related information from the log:
[task 2017-09-26T01:32:52.054Z] 01:32:52  WARNING - Failed to gather test failure debug: Unable to locate window
[task 2017-09-26T01:32:52.055Z] 01:32:52  WARNING - stacktrace:
[task 2017-09-26T01:32:52.056Z] 01:32:52  WARNING - 	WebDriverError@chrome://marionette/content/error.js:239:5
[task 2017-09-26T01:32:52.058Z] 01:32:52  WARNING - 	NoSuchWindowError@chrome://marionette/content/error.js:481:5
[task 2017-09-26T01:32:52.059Z] 01:32:52  WARNING - 	assert.that/<@chrome://marionette/content/assert.js:383:13
[task 2017-09-26T01:32:52.061Z] 01:32:52  WARNING - 	assert.window@chrome://marionette/content/assert.js:117:10
[task 2017-09-26T01:32:52.062Z] 01:32:52  WARNING - 	GeckoDriver.prototype.getPageSource@chrome://marionette/content/driver.js:1184:15
[task 2017-09-26T01:32:52.063Z] 01:32:52  WARNING - 	Async*despatch@chrome://marionette/content/server.js:555:20
[task 2017-09-26T01:32:52.064Z] 01:32:52  WARNING - 	async*execute@chrome://marionette/content/server.js:529:11
[task 2017-09-26T01:32:52.066Z] 01:32:52  WARNING - 	async*onPacket/<@chrome://marionette/content/server.js:504:15
[task 2017-09-26T01:32:52.068Z] 01:32:52  WARNING - 	async*onPacket@chrome://marionette/content/server.js:503:8
[task 2017-09-26T01:32:52.069Z] 01:32:52  WARNING - 	_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:9
[task 2017-09-26T01:32:52.071Z] 01:32:52  WARNING - 
[task 2017-09-26T01:32:52.073Z] 01:32:52     INFO - TEST-UNEXPECTED-ERROR | test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Unable to locate window: 2147483684


I am not sure how to interpret the logs or this specific failure message.

:whimboo- can you help get this in front of the right developer?
Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork]
Joel, this needs a fix on bug 1394351. If the failure rate is increasing maybe we have a chance to track this down. Please note that it's not this test which is affected but basically all tests could be affected which close a window or tab by a click.
Flags: needinfo?(hskupin)
Depends on: 1394351
waiting on a fix in bug 1394351, despite there being no activity there for 2 weeks
We're still waiting for a fix on bug 1394351.
We're still waiting for a fix on bug 1394351.
In the last 7 days, there were 47 failures.
In the past 7 days there are 31 failures. Still waiting for a fix on bug 1394351.
Since one of the latest patches from Andreas this failure has changed in its signature and now shows that the browsing context has gone.

https://treeherder.mozilla.org/logviewer.html#?job_id=156788992&repo=autoland&lineNumber=4537
Flags: needinfo?(ato)
Summary: Intermittent test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Unable to locate window: 2147483684 → Intermittent test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Browsing context has been discarded
Flags: needinfo?(ato)
Depends on: 1431151
Depends on: 1452613
Depends on: 1452653
This bug is about `WebDriver:close`, and is not related to bug 1394351, which is about `WebDriver:click`.
No longer depends on: 1394351, 1452613
Sorry, I mixed up the bugs. It is related to bug 1394351.
Depends on: 1394351
It's only happen for Linux64 ASAN builds in the last time, so it's most likely a race for slow running builds.
status-firefox61: --- → affected
Hardware: Unspecified → x86_64
Fixed by my patch on bug 1452653.
Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox62: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
It's actually not fixed yet. As it looks like `clickElement` is returning too early, or cannot correctly notice that the underlying tab is closing:

> [task 2018-06-08T15:27:08.789Z] 15:27:08     INFO -  1528471628776	Marionette	TRACE	169 -> [0,19,"WebDriver:ElementClick",{"id":"42927a69-d353-45c9-ae23-b7e54526e7d8"}]
> [task 2018-06-08T15:27:09.251Z] 15:27:09     INFO -  1528471629249	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
> [task 2018-06-08T15:27:09.259Z] 15:27:09     INFO -  1528471629255	Marionette	TRACE	169 <- [1,19,null,{"value":null}]
> [task 2018-06-08T15:27:09.268Z] 15:27:09     INFO -  1528471629264	Marionette	TRACE	169 -> [0,20,"WebDriver:GetWindowHandles",{}]
> [task 2018-06-08T15:27:09.269Z] 15:27:09     INFO -  1528471629267	Marionette	TRACE	169 <- [1,20,null,["2147483649","2147483688"]]

Lets see how often it fails...
Status: RESOLVED → REOPENED
status-firefox61: fixed → ---
status-firefox62: fixed → ---
Resolution: FIXED → ---
Target Milestone: mozilla62 → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Browsing context has been discarded → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickCloseContext.test_click_close_tab | NoSuchWindowException: Browsing context has been discarded
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.