geckodriver Click() doesn't wait for page load if submit button delays form submission

System

Version: geckodriver 0.19
Platform: windows 7
Firefox: nightly 58.0a1 (2017-10-22) (64-bit)
Selenium: java 3.6

Testcase

WebDriver driver = new FirefoxDriver();
driver.manage().timeouts().implicitlyWait(10, TimeUnit.SECONDS);
driver.get("http://demo.litecart.net/admin/");
driver.findElement(By.cssSelector("button[name=login]")).click();
driver.findElement(By.cssSelector("a[title=Logout]")).click();
Thread.sleep(200); // to make sure navigation started
driver.get("http://demo.litecart.net/admin/");

It's expected that driver.get(..) operation in the end of this snipped waits until navigation completed, that is until next page loaded after Logout link click.

Instead, it interrupts the operation and Logout does not happen.

Oct 23 '17 16:10 barancev

@barancev can you please supply a trace log? Looks like the click on logout causes a delayed page navigation, and as such we do not wait for it.

Nov 01 '17 19:11 whimboo

Note that I've added Thread.sleep(200) after click. Do you think it's delayed even more?

Trace level log:

1509811879427	geckodriver	INFO	geckodriver 0.19.1
1509811879435	geckodriver	INFO	Listening on 127.0.0.1:31928
1509811880122	mozrunner::runner	INFO	Running command: "C:\\Program Files\\Nightly\\firefox.exe" "-marionette" "-profile" "C:\\Users\\alexei\\AppData\\Local\\Temp\\rust_mozprofile.EmvFv5HgxkDo"
1509811880961	Marionette	DEBUG	Received observer notification "profile-after-change"
1509811881069	Marionette	DEBUG	Received observer notification "command-line-startup"
1509811881069	Marionette	INFO	Enabled via --marionette
1509811881550	geckodriver::marionette	TRACE	  connection attempt 0/600
1509811882072	Marionette	DEBUG	Received observer notification "sessionstore-windows-restored"
1509811882406	Marionette	DEBUG	Setting recommended pref toolkit.cosmeticAnimations.enabled to false
1509811882407	Marionette	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
1509811882408	Marionette	DEBUG	New connections are accepted
1509811882408	Marionette	INFO	Listening on port 53794
1509811882652	geckodriver::marionette	DEBUG	Connected to Marionette on localhost:53794
1509811882653	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:53802
1509811882653	geckodriver::marionette	TRACE	<- {"applicationType":"gecko","marionetteProtocol":3}
1509811882653	geckodriver::marionette	TRACE	-> 163:[0,1,"newSession",{"acceptInsecureCerts":true,"browserName":"firefox","capabilities":{"desiredCapabilities":{"acceptInsecureCerts":true,"browserName":"firefox"}}}]
1509811882654	Marionette	TRACE	0 -> [0,1,"newSession",{"acceptInsecureCerts":true,"browserName":"firefox","capabilities":{"desiredCapabilities":{"acceptInsecureCerts":true,"browserName":"firefox"}}}]
1509811882655	Marionette	WARN	TLS certificate errors will be ignored for this session
1509811882723	Marionette	DEBUG	Register listener.js for window 4294967297
1509811882748	Marionette	TRACE	0 <- [1,1,null,{"sessionId":"e553f82a-7dfe-4662-8c7f-7c8e2a1daad4","capabilities":{}}]
1509811882750	geckodriver::marionette	TRACE	<- [1,1,null,{"sessionId":"e553f82a-7dfe-4662-8c7f-7c8e2a1daad4","capabilities":{"browserName":"firefox","browserVersion":"58.0a1","platformName":"windows_nt","platformVersion":"6.1","pageLoadStrategy":"normal","acceptInsecureCerts":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"rotatable":false,"moz:accessibilityChecks":false,"moz:headless":false,"moz:processID":11780,"moz:profile":"C:\\Users\\alexei\\AppData\\Local\\Temp\\rust_mozprofile.EmvFv5HgxkDo","moz:webdriverClick":true}}]
1509811882750	webdriver::server	DEBUG	<- 200 OK {"value": {"sessionId":"e553f82a-7dfe-4662-8c7f-7c8e2a1daad4","capabilities":{"acceptInsecureCerts":true,"browserName":"firefox","browserVersion":"58.0a1","moz:accessibilityChecks":false,"moz:headless":false,"moz:processID":11780,"moz:profile":"C:\\Users\\alexei\\AppData\\Local\\Temp\\rust_mozprofile.EmvFv5HgxkDo","moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows_nt","platformVersion":"6.1","rotatable":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000}}}}
ноя 04, 2017 7:11:22 PM org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: W3C
Capabilities {acceptInsecureCerts: true, browserName: firefox, browserVersion: 58.0a1, javascriptEnabled: true, moz:accessibilityChecks: false, moz:headless: false, moz:processID: 11780, moz:profile: C:\Users\alexei\AppData\Loc..., moz:webdriverClick: true, pageLoadStrategy: normal, platform: XP, platformName: XP, platformVersion: 6.1, rotatable: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}}
1509811882801	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/timeouts {"implicit":10000}
1509811882801	geckodriver::marionette	TRACE	-> 38:[0,2,"setTimeouts",{"implicit":10000}]
1509811882803	Marionette	TRACE	0 -> [0,2,"setTimeouts",{"implicit":10000}]
1509811882803	Marionette	TRACE	0 <- [1,2,null,{}]
1509811882803	geckodriver::marionette	TRACE	<- [1,2,null,{}]
1509811882803	webdriver::server	DEBUG	<- 200 OK {"value": {}}
1509811882812	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/url {"url":"http://demo.litecart.net/admin/"}
1509811882812	geckodriver::marionette	TRACE	-> 53:[0,3,"get",{"url":"http://demo.litecart.net/admin/"}]
1509811882813	Marionette	TRACE	0 -> [0,3,"get",{"url":"http://demo.litecart.net/admin/"}]
1509811882818	Marionette	DEBUG	Received DOM event "beforeunload" for "about:blank"
1509811883213	Marionette	DEBUG	Received DOM event "pagehide" for "about:blank"
1509811883214	Marionette	DEBUG	Received DOM event "unload" for "about:blank"
1509811883479	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://demo.litecart.net/admin/login.php?redirect_url=%2Fadmin%2F"
1509811883578	Marionette	DEBUG	Received DOM event "pageshow" for "http://demo.litecart.net/admin/login.php?redirect_url=%2Fadmin%2F"
1509811883579	Marionette	TRACE	0 <- [1,3,null,{}]
1509811883580	geckodriver::marionette	TRACE	<- [1,3,null,{}]
1509811883580	webdriver::server	DEBUG	<- 200 OK {"value": {}}
1509811883589	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/element {"value":"button[name\u003dlogin]","using":"css selector"}
1509811883590	geckodriver::marionette	TRACE	-> 73:[0,4,"findElement",{"using":"css selector","value":"button[name=login]"}]
1509811883593	Marionette	TRACE	0 -> [0,4,"findElement",{"using":"css selector","value":"button[name=login]"}]
1509811883596	Marionette	TRACE	0 <- [1,4,null,{"value":{"uuid":"3997b77f-491a-4ca8-8e96-19d957d89348"}}]
1509811883596	geckodriver::marionette	TRACE	<- [1,4,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"3997b77f-491a-4ca8-8e96-19d957d89348","ELEMENT":"3997b77f-491a-4ca8-8e96-19d957d89348"}}]
1509811883596	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"3997b77f-491a-4ca8-8e96-19d957d89348"}}
1509811883605	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/element/3997b77f-491a-4ca8-8e96-19d957d89348/click {"id":"3997b77f-491a-4ca8-8e96-19d957d89348"}
1509811883607	Marionette	TRACE	0 -> [0,5,"clickElement",{"id":"3997b77f-491a-4ca8-8e96-19d957d89348"}]
1509811883606	geckodriver::marionette	TRACE	-> 66:[0,5,"clickElement",{"id":"3997b77f-491a-4ca8-8e96-19d957d89348"}]
1509811883843	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
1509811883844	Marionette	TRACE	0 <- [1,5,null,{}]
1509811883844	geckodriver::marionette	TRACE	<- [1,5,null,{}]
1509811883844	webdriver::server	DEBUG	<- 200 OK {"value": {}}
1509811883851	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/element {"value":"a[title\u003dLogout]","using":"css selector"}
1509811883851	geckodriver::marionette	TRACE	-> 70:[0,6,"findElement",{"using":"css selector","value":"a[title=Logout]"}]
1509811883852	Marionette	TRACE	0 -> [0,6,"findElement",{"using":"css selector","value":"a[title=Logout]"}]
1509811884946	Marionette	TRACE	0 <- [1,6,null,{"value":{"uuid":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}}]
1509811884948	geckodriver::marionette	TRACE	<- [1,6,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d","ELEMENT":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}}]
1509811884948	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}}
1509811884958	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/element/e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d/click {"id":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}
1509811884958	geckodriver::marionette	TRACE	-> 66:[0,7,"clickElement",{"id":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}]
1509811884959	Marionette	TRACE	0 -> [0,7,"clickElement",{"id":"e5f6f7cb-58ef-48f8-824b-fe8ff85c6c8d"}]
1509811885181	Marionette	DEBUG	Canceled page load listener because no navigation has been detected
1509811885182	Marionette	TRACE	0 <- [1,7,null,{}]
1509811885182	geckodriver::marionette	TRACE	<- [1,7,null,{}]
1509811885182	webdriver::server	DEBUG	<- 200 OK {"value": {}}
1509811885390	webdriver::server	DEBUG	-> POST /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4/url {"url":"http://demo.litecart.net/admin/"}
1509811885390	geckodriver::marionette	TRACE	-> 53:[0,8,"get",{"url":"http://demo.litecart.net/admin/"}]
1509811885391	Marionette	TRACE	0 -> [0,8,"get",{"url":"http://demo.litecart.net/admin/"}]
1509811885393	Marionette	DEBUG	Received DOM event "beforeunload" for "http://demo.litecart.net/admin/"
1509811885586	Marionette	DEBUG	Received DOM event "pagehide" for "http://demo.litecart.net/admin/"
1509811885586	Marionette	DEBUG	Received DOM event "unload" for "http://demo.litecart.net/admin/"
1509811885649	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://demo.litecart.net/admin/"
1509811885650	Marionette	DEBUG	Received DOM event "pageshow" for "http://demo.litecart.net/admin/"
1509811885651	Marionette	TRACE	0 <- [1,8,null,{}]
1509811885654	geckodriver::marionette	TRACE	<- [1,8,null,{}]
1509811885654	webdriver::server	DEBUG	<- 200 OK {"value": {}}
1509811885660	webdriver::server	DEBUG	-> DELETE /session/e553f82a-7dfe-4662-8c7f-7c8e2a1daad4 
1509811885661	geckodriver::marionette	TRACE	-> 37:[0,9,"quit",{"flags":["eForceQuit"]}]
1509811885661	Marionette	TRACE	0 -> [0,9,"quit",{"flags":["eForceQuit"]}]
1509811885662	Marionette	DEBUG	New connections will no longer be accepted
Unable to read VR Path Registry from C:\Users\alexei\AppData\Local\openvr\openvrpaths.vrpath
[Child 13940, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
[Child 13940, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
1509811885710	Marionette	TRACE	0 <- [1,9,null,{"cause":"shutdown"}]
1509811885723	geckodriver::marionette	TRACE	<- [1,9,null,{"cause":"shutdown"}]
1509811885723	webdriver::server	DEBUG	Deleting session
1509811885723	geckodriver::marionette	DEBUG	Stopping browser process
1509811885914	webdriver::server	DEBUG	<- 200 OK {"value": {}}

Nov 04 '17 16:11 barancev

So as it looks like the logout link is not immediately clickable when the page has been finished loading. In my test I have to add another 200ms delay between retrieving this element, and before being able to click on it. With that delay included it works all fine.

Nov 08 '17 10:11 whimboo

The link is immediately clickable. It's a plain 'a' element with 'href' attribute. It's clickable as soon as it's visible.

I can reproduce the issue on other sites too.

No other driver I tried (legacy Firefox driver, Chrome driver, IE driver) has this issue. They all wait for navigation complete.

Nov 08 '17 11:11 barancev

Ah. Wait, we indeed return too early from the first call to click (login) because no page navigation is seen within 200ms which is our internal timeout. When I increase this value I can see the following:

1510141459790	Marionette	TRACE	3 -> [0,13,"clickElement",{"id":"71938d43-19de-3642-9de8-305a38354baa"}]
1510141460841	Marionette	DEBUG	Received DOM event "beforeunload" for "http://demo.litecart.net/admin/login.php?redirect_url=%2Fadmin%2F"

So as you can see it takes up to 1s until the beforeunload handler actually gets fired. This is very suspicious, and as such I checked with the developer tools why there is such a delay.

The login_form has a customized handler for submit, which looks like:

function(e) {
  e.preventDefault();
  var form = this;
  $('#box-login-wrapper .content').slideUp(250, function() {
    $('#box-login-wrapper').fadeOut(500, function() {
      $('.loader-wrapper').fadeIn(250, function() {
        form.submit();
      });
    });
  });
}

So before the actual submit of the form happens, which would trigger the page load, there are actually a couple of graphical gimmicks executed. All of them count up to 1000ms, which is the delay I was able to see above.

No other driver as listed above is webdriver-spec compliant, right? Maybe there is something we miss to account for, or it's something which is missing in the spec.

@andreastt, do you have an idea?

Nov 08 '17 12:11 whimboo

So by working on changes for sendKeys and making changes to our test cases I noticed that when clicking a submit button, two distinct events are getting fired. First, the click event from the submit button, and second the submit event of the form.

I think we have to extend our logic for click + pageload to not only wait for the click being done, but to also wait for the form being submitted if the clicked element is a form element.

With this change the above test case should be working.

Nov 10 '17 13:11 whimboo

I filed bug 1416216 to get this fixed.

Nov 10 '17 13:11 whimboo

Is there a workaround until this issue has been fixed? Do I understand it right that first the w3c has to fix this issue? How long could that be?

Dec 04 '17 15:12 q-jack

Just wait for a specific element of the target page to become present. That should work in most cases. I cannot say how long it will take to get this clarified and implemented.

Dec 05 '17 14:12 whimboo

I already tried the both types of waits, the pageload does not happen except when I open the inspect tool, switch to network and check the persist all checkbox. then the pageload is happening

Dec 05 '17 15:12 q-jack

@q-jack can we please continue on issue #1090 until it's not clear that it is a duplicate? Thanks

Dec 06 '17 06:12 whimboo

I'm currently triaging old issues and noticed that one. Given that I updated Element Click recently we agreed on that there is no guarantee that cases like this can be handled by the driver itself. If navigations are triggered with a delay there is nothing we can do. The driver can't just wait some seconds for each and every click. As such a tradeoff has to be made, which in our case is currently the 250ms delay.

To get this working the test code would have to wait for the logout button to be interactable.

Also note that chromedriver / Chrome fails the same way.

Closing the issue given that we are not going to fix it.

Oct 23 '20 09:10 whimboo

I disagree. The issue is not related to "click" operation. The essense is that the "get" operation does not wait till the current navigation is complete, it interrupts the navigation.

Oct 23 '20 09:10 barancev

Nothing in the WebDriver spec says that the [Navigate To](https://w3c.github.io/webdriver/#dfn-navigate-to] command has to wait until a currently active navigation is complete. In fact the problem is that this page delays the page load for login and logout by nearly a second because of a custom form submit handler! See these log entries:

1604069904016	Marionette	DEBUG	2 -> [0,12,"WebDriver:ElementClick",{"id":"c1690a0d-ff6e-6648-b0f4-1db0a6aa0c3b"}]
1604069904026	Marionette	TRACE	Received DOM event click for [object HTMLButtonElement]
1604069905042	Marionette	TRACE	Received message beforeunload for https://demo.litecart.net/admin/login.php

Then by checking bug 1416216 (as referenced above) I noticed that I filed a webdriver issue at https://github.com/w3c/webdriver/issues/1166.

I'm fine with keeping this issue open for now until a solution for webdriver has been found.

Oct 30 '20 15:10 whimboo

geckodriver geckodriver copied to clipboard

Click() doesn't wait for page load if submit button delays form submission

System

Testcase

geckodriver
geckodriver copied to clipboard