page.waitForNavigation causes time out

inancgumus commented 2 years ago

Please see https://github.com/grafana/xk6-browser/issues/200#issuecomment-1033194052 and https://github.com/grafana/xk6-browser/issues/200#issuecomment-1033198708 for details.

Adding page.waitForNavigation(); in place of page.waitForSelector('div.cb-content'); caused a waitForFrameNavigation timed out after 30s.

Script Source

```js import launcher from 'k6/x/browser'; import { group, sleep } from 'k6'; export default function () { const browser = launcher.launch('chromium', { headless: false, }); const context = browser.newContext({ }); const page = context.newPage(); group("Navigate to Homepage", () => { page.goto('https://trollflix.com'); // without the below waitForSelector, the page.$$ expression returns a length of 0 page.waitForSelector('div.cb-content'); // required here even if I were to use waitUntil: 'networkidle' above // grab the number of displayed videos (should be 12) const videoCount = page.$$('div.cb-content').length; console.log(`Found ${videoCount} in page`); }); sleep(2); group("Filter by Gaming", () => { page.hover('#hn-categories'); sleep(1); // without the below waitForSelector, the page.$$ expression returns a length of 0 (interestingly, not the previous value - 12 - so the expression was evaluated after the page partially refreshed) page.$('//div[text()="Gaming"]').click(); page.waitForSelector('div.cb-content'); // waiting for the div here ensures the videoCount updates as expected // grab the number of displayed videos (should be 2) const videoCount = page.$$('div.cb-content').length; console.log(`Found ${videoCount} in page`); }); } ```

imiric commented 2 years ago

I ran into this as well while testing the staging app. Looking into it.

It could be considered part of #200 though.

imiric commented 2 years ago

I've been looking into this issue, and it seems to happen when the navigation happens within the same document, e.g. by using the History API.

In these cases the Page.navigatedWithinDocument event is received, for which we properly emit the internal NavigationEvent, but in WaitForFrameNavigation() we also wait for a FrameAddLifecycle event: https://github.com/grafana/xk6-browser/blob/917b83ef14b3e2075f92c092163c47e359883a6a/common/frame_manager.go#L725-L736

... which is never emitted in these internal navigations, so the wait times out.

I'm still not sure what the correct fix would be, and will keep investigating.

imiric commented 2 years ago

Here's a test that reproduces the issue:

package tests

import (
    "net/http"
    "testing"
    "time"

    "github.com/grafana/xk6-browser/common"
    "github.com/stretchr/testify/require"
)

var navHTML = `
<html>
  <head>
    <title>History API navigation test</title>
  </head>
  <body>
    <a id="navigate" href="#">Navigate</a>
    <script>
      const el = document.querySelector('a#navigate');
      el.addEventListener('click', function(evt) {
        evt.preventDefault();
        history.pushState({}, 'navigated', '/nav2');
      });
    </script>
  </body>
</html>
`

func TestWaitForFrameNavigationWithinDocument(t *testing.T) {
    tb := newTestBrowser(t, withHTTPServer())
    tb.withHandler("/nav", http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
        w.Header().Set("Content-Type", "text/html")
        w.Write([]byte(navHTML))
    }))
    p := tb.NewPage(nil)

    resp := p.Goto(tb.URL("/nav"), nil)
    require.NotNil(t, resp)

    el := p.Query("a#navigate")
    require.NotNil(t, el)
    // A click right away could possibly trigger navigation before we had a
    // chance to call WaitForNavigation below, so give it some time to simulate
    // the JS overhead, waiting for XHR response, etc.
    time.AfterFunc(200*time.Millisecond, func() {
        el.Click(nil)
    })

    p.WaitForNavigation(tb.rt.ToValue(&common.FrameWaitForNavigationOptions{
        Timeout: 1000, // 1s
    }))
}

Running it results in:

--- FAIL: TestWaitForFrameNavigationWithinDocument (1.64s)
panic: waitForFrameNavigation cannot wait for event (EventFrameAddLifecycle): timed out [recovered]
        panic: waitForFrameNavigation cannot wait for event (EventFrameAddLifecycle): timed out

goroutine 24 [running]:
testing.tRunner.func1.2({0x1107ba0, 0xc000814b40})
        /home/ivan/.local/share/go/src/testing/testing.go:1209 +0x24e
testing.tRunner.func1()
        /home/ivan/.local/share/go/src/testing/testing.go:1212 +0x218
panic({0x1107ba0, 0xc000814b40})
        /home/ivan/.local/share/go/src/runtime/panic.go:1038 +0x215
go.k6.io/k6/js/common.Throw(0xf9b540, {0x12bf7c0, 0xc000812b10})
        /home/ivan/Projects/grafana/xk6-browser/vendor/go.k6.io/k6/js/common/util.go:36 +0x55
github.com/grafana/xk6-browser/common.k6Throw({0x12dc320, 0xc000932d80}, {0x11800b8, 0x49}, {0xc000455d28, 0x1, 0x1})
        /home/ivan/Projects/grafana/xk6-browser/common/helpers.go:214 +0x1ae
github.com/grafana/xk6-browser/common.(*FrameManager).WaitForFrameNavigation(0xc000584160, 0x5, {0x12f52f8, 0xc0008140c0})
        /home/ivan/Projects/grafana/xk6-browser/common/frame_manager.go:734 +0x94c
github.com/grafana/xk6-browser/common.(*Frame).WaitForNavigation(...)
        /home/ivan/Projects/grafana/xk6-browser/common/frame.go:1434
github.com/grafana/xk6-browser/common.(*Page).WaitForNavigation(0xc0008f2140, {0x12f52f8, 0xc0008140c0})
        /home/ivan/Projects/grafana/xk6-browser/common/page.go:881 +0xd7
github.com/grafana/xk6-browser/tests.TestWaitForFrameNavigationWithinDocument(0x0)
        /home/ivan/Projects/grafana/xk6-browser/tests/frame_manager_nav_test.go:50 +0x22e
testing.tRunner(0xc000623380, 0x11997f0)
        /home/ivan/.local/share/go/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
        /home/ivan/.local/share/go/src/testing/testing.go:1306 +0x35a
FAIL    github.com/grafana/xk6-browser/tests    1.659s

I'm still looking into the possible fix.

One possible option would be to emit a separate NavigationWithinDocumentEvent for which we don't wait for the FrameAddLifecycle event. I'll explore this tomorrow.

grafana / xk6-browser

page.waitForNavigation causes time out #226