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

barancev commented 6 years ago

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.

whimboo commented 6 years ago

@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.

barancev commented 6 years ago

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": {}}

whimboo commented 6 years ago

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.

barancev commented 6 years ago

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.

whimboo commented 6 years ago

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?

whimboo commented 6 years ago

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.

whimboo commented 6 years ago

I filed bug 1416216 to get this fixed.

q-jack commented 6 years ago

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?

whimboo commented 6 years ago

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.

q-jack commented 6 years ago

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

whimboo commented 6 years ago

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

whimboo commented 3 years ago

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.

barancev commented 3 years ago

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.

whimboo commented 3 years ago

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.

mozilla / geckodriver

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

System

Testcase