1418273 - WebDriver:Navigate hangs when surfing to a page that is blocked by an extension

Status: NEW

(Remote Protocol :: Marionette, defect, P3)

Description

[Gertjan]

Attachment: Console output of marionette

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94 Safari/537.36

Steps to reproduce:

For automated testing purposes, I start Firefox 56.0.2 with the uBlock Origin extension loaded through Selenium 3.6.0 and Geckodriver 0.19.1. Then I order this Firefox instance to visit a website which is blocked by the uBlock Origin extension, in this case "https://desk.cmix.org".

The following Java code reproduces the problem:

public static  void main(String[] args) throws InterruptedException {
        FirefoxProfile profile = new FirefoxProfile();
        profile.addExtension(new File("ublock_origin-1.14.18.xpi"));
        FirefoxOptions options = new FirefoxOptions();
        options.setProfile(profile);
        WebDriver driver = new FirefoxDriver(options);
        Thread.sleep(2000);
        driver.get("https://desk.cmix.org");
        Thread.sleep(2000);
        driver.get("https://desk.cmix.org");
        Thread.sleep(2000);
        driver.get("https://desk.cmix.org");
        driver.quit();
}


Actual results:

As intended, the Firefox instance will show a warning page instead of the actual contents of the blocked website. However, after the first or sometimes second call of the get method, the program hangs indefinitely. In other words, the program will never return from the first or sometimes second get call.


Expected results:

The program should not hang after calling the get method.

Comment 1

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

Thank you for the report, and would you mind attaching a trace level log? See https://firefox-source-docs.mozilla.org/testing/geckodriver/geckodriver/TraceLogs.html in how to get one.

This will give me additional information to get it investigated. Thanks.

Comment 2

[Gertjan]

Attachment: Console output of marionette (TRACE logs enabled)

Comment 3

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

Thanks!

So the first page load from about:blank to that URL is working fine:

1510918769691	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "about:blank"
1510918769749	addons.productaddons	INFO	Downloaded file will be saved to /var/folders/md/zqq47w792mb4jtbx_66c0pfw0000gn/T/tmpaddon-76f197
1510918769808	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "moz-extension://efc663d8-1021-6c4b-a83d-45bd9e7ce298/document-blocked.html?details=eyJ1cmwiOiJodHRwczovL2Rlc2suY21peC5vcmcvIiwiaG4iOiJkZXNrLmNtaXgub3JnIiwiZG4iOiJjbWl4Lm9yZyIsImZjIjoiWzAsNjIsXCJkZXNrLmNtaXgub3JnXCJdIiwiZnMiOiJ8fGRlc2suY21peC5vcmdeIn0="
1510918769835	Marionette	DEBUG	Received DOM event "pageshow" for "moz-extension://efc663d8-1021-6c4b-a83d-45bd9e7ce298/document-blocked.html?details=eyJ1cmwiOiJodHRwczovL2Rlc2suY21peC5vcmcvIiwiaG4iOiJkZXNrLmNtaXgub3JnIiwiZG4iOiJjbWl4Lm9yZyIsImZjIjoiWzAsNjIsXCJkZXNrLmNtaXgub3JnXCJdIiwiZnMiOiJ8fGRlc2suY21peC5vcmdeIn0="
1510918769840	Marionette	TRACE	0 <- [1,2,null,{}]

But then loading the same page again causes the problem:

1510918771848	Marionette	TRACE	0 -> [0,3,"get",{"url":"https://desk.cmix.org"}]
1510918771850	Marionette	DEBUG	Received DOM event "beforeunload" for "moz-extension://efc663d8-1021-6c4b-a83d-45bd9e7ce298/document-blocked.html?details=eyJ1cmwiOiJodHRwczovL2Rlc2suY21peC5vcmcvIiwiaG4iOiJkZXNrLmNtaXgub3JnIiwiZG4iOiJjbWl4Lm9yZyIsImZjIjoiWzAsNjIsXCJkZXNrLmNtaXgub3JnXCJdIiwiZnMiOiJ8fGRlc2suY21peC5vcmdeIn0="
1510918771856	Marionette	DEBUG	Received DOM event "pagehide" for "moz-extension://efc663d8-1021-6c4b-a83d-45bd9e7ce298/document-blocked.html?details=eyJ1cmwiOiJodHRwczovL2Rlc2suY21peC5vcmcvIiwiaG4iOiJkZXNrLmNtaXgub3JnIiwiZG4iOiJjbWl4Lm9yZyIsImZjIjoiWzAsNjIsXCJkZXNrLmNtaXgub3JnXCJdIiwiZnMiOiJ8fGRlc2suY21peC5vcmdeIn0="
1510918771856	Marionette	DEBUG	Received DOM event "unload" for "moz-extension://efc663d8-1021-6c4b-a83d-45bd9e7ce298/document-blocked.html?details=eyJ1cmwiOiJodHRwczovL2Rlc2suY21peC5vcmcvIiwiaG4iOiJkZXNrLmNtaXgub3JnIiwiZG4iOiJjbWl4Lm9yZyIsImZjIjoiWzAsNjIsXCJkZXNrLmNtaXgub3JnXCJdIiwiZnMiOiJ8fGRlc2suY21peC5vcmdeIn0="
1510918771897	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "24"
1510918772061	Marionette	DEBUG	Register listener.js for window 4294967297
1510918772129	Marionette	DEBUG	Check readyState "uninitialized for "about:blank"
1510918772169	Marionette	DEBUG	Register listener.js for window 28


Maybe this is related to all the remoteness changes occurring here, from handle `24` to `4294967297`, and then `28`. Usually when we receive `outer-window-destroyed` the page load should be aborted.

Comment 4

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

Yeah, so after looking at the code I think the `curBrowser.pendingCommands` list is messed up because the command id of the currently running `get` request has been removed, and another frame script registration does not resolve the promise anymore.