1411264 - click doesn't wait for two successive page loads

Status: RESOLVED WONTFIX

(Remote Protocol :: Marionette, defect, P3)

Description

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Originally raised as https://github.com/mozilla/geckodriver/issues/911, I have now reduced this test case down to a link that changes the window.location.hash and then loads another URL. It appears that websites built on Angular (such as the current implementation of Treeherder) modify window.location.hash [1], and in the case of Treeherder, this is conditionally followed by a window.location.reload() [2].

Since bug 1386977, Marionette appears to be aborting the page load algorithm when a "popstate" event is fired. It appears that in addition to navigating back/forward, this event is also fired when location.hash is changed.

I will attach a patch with a failing test that replicates this issue. The popstate event can be observed by pasting the following into the web console for any page:

> window.addEventListener("popstate", function (e) {console.log(e)});
> window.location.hash = 'foo';

[1] https://github.com/angular/angular.js/blob/32fbb2e78f53d765fbb170f7cf99e42e072d363b/src/ng/browser.js#L161
[2] https://github.com/mozilla/treeherder/blob/4acbfb17c01f7f6aa240b2c14bcd279b6c57d626/ui/js/controllers/main.js#L677

Comment 1

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Attachment: Bug 1411264: Add failing test for click with hash change not waiting for subsequent page load.

Review commit: https://reviewboard.mozilla.org/r/192520/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/192520/

Comment 2

[Ed Morley [:emorley]]

Great sleuthing! Thank you for tracking this down :-)

Comment 3

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/6b80a95ed4d8ea0414668becaf8158764ed017f2
Jenkins: Improve range tests by working around bug 1411264 and picking result sets relative to the end of the list (#2871)

Comment 4

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/987e921a8fa7fecfa30290ccb1b7c47d6e41a9c0
Jenkins: Improve tests that filter by email by working around bug 1411264 (#2873)

Comment 5

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/460d7c4d1bcb85a24fb63a0e50ba3f60dfb6d61a
Jenkins: Improve test_open_single_result by working around bug 1411264 and viewing a random result set (#2874)

Comment 6

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

Please also note bug 1411393. Due to registering for `beforeunload` in Marionette the bfcache will never be used for navigation. I would say lets wait for this other bug to be fixed first.

Comment 7

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/4fab107dfd4eafc628dfe4bf078663221adc86cd
Jenkins: Improve test_switch_repo by working around bug 1411264 (#2885)

Comment 8

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

Dave, would you mind testing again with the latest mozilla-central code, or the upcoming nightly build later today?

Comment 9

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Raphael: Could you report your findings from running the test in the patch against a recent Nightly build?

Comment 10

[Raphael Aurich [:raphael] UTC+01:00]

Dave: Hope this helps!

# Revision

``c5c9f7f98d19 tip central``

## FirefoxNightly

### Version

``59.0a1 (2017-11-20) (64-bit) on OS X``

### Command

``./mach marionette test --binary /Applications/FirefoxNightly.app/Contents/MacOS/firefox-bin testing/marionette/harness/marionette_harness/tests/unit/test_click.py``

### Output

```text
Summary
=======

Ran 38 tests
Expected results: 37
Unexpected results: 1 (FAIL: 1)

Unexpected Results
==================

FAIL test_click.py TestClickNavigation.test_click_link_page_load_after_hash_change

Traceback (most recent call last):
  File "mozilla-unified/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 156, in run
    testMethod()
  File "mozilla-unified/testing/marionette/harness/marionette_harness/tests/unit/test_click.py", line 348, in test_click_link_page_load_after_hash_change
    self.assertEqual(self.marionette.title, "Slow page loading")
AssertionError: u'Testing Clicks' != 'Slow page loading'
```

## Firefox

### Version

``57.0 (64-bit) on OS X``

### Command

``./mach marionette test --binary /Applications/Firefox.app/Contents/MacOS/firefox-bin testing/marionette/harness/marionette_harness/tests/unit/test_click.py``

### Output

```text
Summary
=======

Ran 38 tests
Expected results: 37
Unexpected results: 1 (FAIL: 1)

Unexpected Results
==================

FAIL test_click.py TestClickNavigation.test_click_link_page_load_after_hash_change

Traceback (most recent call last):
  File "mozilla-unified/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 156, in run
    testMethod()
  File "mozilla-unified/testing/marionette/harness/marionette_harness/tests/unit/test_click.py", line 348, in test_click_link_page_load_after_hash_change
    self.assertEqual(self.marionette.title, "Slow page loading")
AssertionError: u'Testing Clicks' != 'Slow page loading'
```

Comment 11

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Thanks Raphael! Henrik, did you mention that there's another bug in progress that once resolved might also impact this?

Comment 12

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

So I finally had the chance to take a look at this test. The problem we have here is that when clicking the link, there are two individual page load actions triggered by Javascript:

> <a href="javascript:window.location.hash = 'foo'; window.location = 'slow?delay=1'" id="hash-location">hash+location</a>

1) The hash of the current location is getting updated. As such we should receive a `hashchange` event. Interestingly I see a `popstate` event being fired. But that would warrant a different investigation

1511962904870	Marionette	TRACE	3 -> [0,8,"clickElement",{"id":"39f23b43-8de9-bd4e-8b7c-c40dcb77f9ce"}]
1511962904916	Marionette	DEBUG	Received DOM event "popstate" for "http://127.0.0.1:61185/clicks.html#foo"
1511962904917	Marionette	DEBUG	Received DOM event "beforeunload" for "http://127.0.0.1:61185/clicks.html#foo"
1511962904926	Marionette	DEBUG	Received DOM event "hashchange" for "http://127.0.0.1:61185/clicks.html#foo"

2) The location gets replaced completely right afterward, which triggers another full page load.

1511962905951	Marionette	DEBUG	Received DOM event "pagehide" for "http://127.0.0.1:61185/clicks.html#foo"
1511962905952	Marionette	DEBUG	Received DOM event "unload" for "http://127.0.0.1:61185/clicks.html#foo"
++DOMWINDOW == 5 (0x114c30400) [pid = 13169] [serial = 5] [outer = 0x10d239e20]
1511962905972	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://127.0.0.1:61185/slow?delay=1"
1511962905977	Marionette	DEBUG	Received DOM event "pageshow" for "http://127.0.0.1:61185/slow?delay=1"

So click() itself takes care of 1) because that is the page load action it waits for. It doesn't know about 2).

AFAIR we do not want that click() waits for the page loads for kinda complex Javascript code.

David, what is your take here?

Comment 13

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

Comment on attachment 8921480 [details]
Bug 1411264: Add failing test for click with hash change not waiting for subsequent page load.

https://reviewboard.mozilla.org/r/192520/#review209542

Comment 14

[David Burns :automatedtester]

We should only wait for one of the page changes. Its bizarre that a hash change then creates a web page reload. We won't be supporting this use case.

Comment 15

[Dave Hunt [:davehunt] [he/him] ⌚BST]

It's worth noting that the legacy Firefox driver from Selenium did not suffer from this issue. I'm not sure if this influences the decision, but it may be seen as a regression for upgrading their tests from an old version of Firefox. It's also not immediately obvious what's happening, and can take a while to identify the edge case.

For any readers that are experiencing this issue, a workaround is either to wait for an element attribute that is true after the resulting page load. If there's little to distinguish the incoming page from the outgoing, then first wait for the <body> element to be stale, and then wait for the appropriate element attribute.

Comment 16

[David Burns :automatedtester]

(In reply to Dave Hunt (:davehunt) from comment #15)
> It's worth noting that the legacy Firefox driver from Selenium did not
> suffer from this issue. I'm not sure if this influences the decision, but it
> may be seen as a regression for upgrading their tests from an old version of
> Firefox. It's also not immediately obvious what's happening, and can take a
> while to identify the edge case.

I think its just a race condition luck of the draw here. Looking at legacy firefox driver if it looks like a hash change it doesnt expect a load https://github.com/SeleniumHQ/selenium/blob/master/javascript/firefox-driver/js/webLoadingListener.js#L50-L57.

Either its hitting that code when the hash part is finished and knows its just a page change, who knows.

Comment 17

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

The old Firefox driver uses a webprogress listener. Maybe that one behaves a bit differnet, and would recognize an immediate following page load?

Comment 18

[David Burns :automatedtester]

[Mass Change 2018-01-15] Moving bugs to backlog

Comment 19

[Pete Savage]

(In reply to Dave Hunt [:davehunt] ⌚️UTC+0  from comment #15)
> It's worth noting that the legacy Firefox driver from Selenium did not
> suffer from this issue. I'm not sure if this influences the decision, but it
> may be seen as a regression for upgrading their tests from an old version of
> Firefox. It's also not immediately obvious what's happening, and can take a
> while to identify the edge case.
> 
> For any readers that are experiencing this issue, a workaround is either to
> wait for an element attribute that is true after the resulting page load. If
> there's little to distinguish the incoming page from the outgoing, then
> first wait for the <body> element to be stale, and then wait for the
> appropriate element attribute.

Absolutely we are seeing this and it definitely feels like a regression. We have been testing against FF since 45ESR and have just started looking at switching to newer versions due to the issues we have had before with Marionette and Gecko. This was tripping me up for a while. All my code appeared to be just like before, except after a click, our view was being returned a lot quicker than I expected. Though we have some relatively sophisticated code to check if the page is ready for interaction, the fact that we hadn't even left the previous page, tricked it into thinking we were ready for interaction. Of course that meant we were on the old page and so the elements didn't exist and tears ensued.

I will try implementing the suggested fix (it was what I was close to what I was going to try any way, but it would be a real help to have this fixed.

Comment 20

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

Please see comment 14. It's not that clear in the spec yet as it seems:
https://w3c.github.io/webdriver/webdriver-spec.html#dfn-waiting-for-the-navigation-to-complete

Andreas or David, was there some clarification lately? I cannot find a webdriver spec issue which would make this clear.

Comment 21

[David Burns :automatedtester]

(In reply to Henrik Skupin (:whimboo) from comment #20)
> Please see comment 14. It's not that clear in the spec yet as it seems:
> https://w3c.github.io/webdriver/webdriver-spec.html#dfn-waiting-for-the-
> navigation-to-complete
> 
> Andreas or David, was there some clarification lately? I cannot find a
> webdriver spec issue which would make this clear.

Looking at the spec I am not sure what we can add here nor what we can do here to solve this issue.