From 19a5df8378a6798cdeb0919c75c0d606e6b210af Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ivan=20Miri=C4=87?= Date: Tue, 22 Mar 2022 17:06:12 +0100 Subject: [PATCH] Refactor waitForNavigation to reduce chances of race conditions The previous way of waiting for navigation events had a couple of issues: - There was a race condition where the Page.frameNavigated CDP event was received before we had a chance to setup the waiter for it, causing timeouts (#272). - The implementation was repeated two times in FrameManager (NavigateFrame and WaitForNavigation). This change tries to setup the waiters concurrently with the FrameSession.navigateFrame call, which minimizes--but doesn't completely eliminate--the chance of a missed event and timeout. It also moves the implementation to Frame and reuses it for both Goto and WaitForNavigation. There's another version of this in Page.Reload which I didn't bother changing here. It also does the JS option parsing upfront in the functions exported to the script, so that internally we don't depend on goja.Runtime (part of #271). It's currently not possible to completely avoid the race, since there's no way to synchronize when the waiters are actually started (i.e. when the goroutine in createWaitForEventHandler is started). There's another issue with Page.Goto when it sometimes returns a nil Response. I tried fixing this by adding another waiter for EventPageResponse, but that turned out to be racy as well (e.g. on internal pages like about:blank or data URIs). Fixing these issues will require a major change in how events are handled internally. Closes #272 --- common/frame.go | 179 ++++++++++++++++++++++++++++++++++++++- common/frame_manager.go | 180 ---------------------------------------- 2 files changed, 176 insertions(+), 183 deletions(-) diff --git a/common/frame.go b/common/frame.go index 7ea0d9421..2777f8f3e 100644 --- a/common/frame.go +++ b/common/frame.go @@ -921,8 +921,70 @@ func (f *Frame) GetAttribute(selector string, name string, opts goja.Value) goja // Goto will navigate the frame to the specified URL and return a HTTP response object. func (f *Frame) Goto(url string, opts goja.Value) api.Response { - resp := f.manager.NavigateFrame(f, url, opts) + netMgr := f.page.mainFrameSession.getNetworkManager() + defaultReferer := netMgr.extraHTTPHeaders["referer"] + parsedOpts := NewFrameGotoOptions(defaultReferer, + time.Duration(f.manager.timeoutSettings.navigationTimeout())*time.Second) + if err := parsedOpts.Parse(f.ctx, opts); err != nil { + k6Throw(f.ctx, "failed parsing goto options: %w", err) + } + + resp := f.navigate(url, parsedOpts) applySlowMo(f.ctx) + + return resp +} + +func (f *Frame) navigate(url string, opts *FrameGotoOptions) api.Response { + var ( + fid = f.ID() + furl = f.URL() + ) + f.logger.Debugf("Frame:navigate", + "fid:%v furl:%s url:%s", fid, furl, url) + defer f.logger.Debugf("Frame:navigate:return", + "fid:%v furl:%s url:%s", fid, furl, url) + + fs := f.page.getFrameSession(cdp.FrameID(fid)) + if fs == nil { + f.logger.Debugf("Frame:navigate", + "fid:%v furl:%s url:%s fs:nil", fid, furl, url) + + // Attaching an iframe to an existing page doesn't seem to trigger a "Target.attachedToTarget" event + // from the browser even when "Target.setAutoAttach" is true. If this is the case fallback to the + // main frame's session. + fs = f.page.mainFrameSession + } + + var ( + navCh = make(chan string) + navCtx, navCtxCancel = context.WithCancel(f.ctx) + resp api.Response + wg sync.WaitGroup + ) + defer navCtxCancel() + + wg.Add(1) + // Try to setup waiters first, to minimize the chances of a race condition + // where we receive Page.frameNavigated / Network.responseReceived before we + // have a chance to listen to them, leading to timeouts. + go func() { + defer wg.Done() + resp = f.waitForNavigation(navCtx, &FrameWaitForNavigationOptions{ + URL: url, + WaitUntil: opts.WaitUntil, + Timeout: opts.Timeout, + }, navCh) + }() + + docID, err := fs.navigateFrame(f, url, opts.Referer) + if err != nil { + k6Throw(f.ctx, "error navigating frame: %s", err) + } + + navCh <- docID + wg.Wait() + return resp } @@ -1546,9 +1608,120 @@ func (f *Frame) WaitForLoadState(state string, opts goja.Value) { } } -// WaitForNavigation waits for the given navigation lifecycle event to happen. +// WaitForNavigation waits for NavigationEvent to be emitted, and in case of +// cross-document navigations (i.e. not for navigations within the same document +// done via an anchor link or the history API) it also waits for a LifecycleEvent. func (f *Frame) WaitForNavigation(opts goja.Value) api.Response { - return f.manager.WaitForFrameNavigation(f, opts) + parsedOpts := NewFrameWaitForNavigationOptions(time.Duration(f.manager.timeoutSettings.timeout()) * time.Second) + if err := parsedOpts.Parse(f.ctx, opts); err != nil { + k6Throw(f.ctx, "error parsing waitForNavigation options: %v", err) + } + + return f.waitForNavigation(f.ctx, parsedOpts, nil) +} + +// waitForNavHandler determines whether a received NavigationEvent +// matches the specific document navigation happened for, otherwise +// it assumes it was a navigation for the same document. +func waitForNavHandler(data interface{}, getDocID func() string) bool { + ev, _ := data.(*NavigationEvent) + + // There was a Page.navigate command issued, so wait for the returned document ID. + if getDocID != nil { + docID := getDocID() + if docID != "" { + // We are interested either in this specific document, or any other document that + // did commit and replaced the expected document. + if ev.newDocument != nil && + (ev.newDocument.documentID == docID || ev.err == nil) { + return true + } + return false + } + } + + // Both successful and failed navigations are considered + return true +} + +//nolint: cyclop,funlen +func (f *Frame) waitForNavigation( + ctx context.Context, opts *FrameWaitForNavigationOptions, navCh <-chan string, +) api.Response { + f.logger.Debugf("Frame:waitForNavigation", "fid:%s furl:%s", f.ID(), f.URL()) + defer f.logger.Debugf("Frame:waitForNavigation:return", "fid:%s furl:%s", f.ID(), f.URL()) + + var getDocID func() string + if navCh != nil { + var docID string + getDocID = func() string { + if docID == "" { + docID = <-navCh + } + return docID + } + } + + timeoutCtx, timeoutCancelFn := context.WithTimeout(ctx, opts.Timeout) + defer timeoutCancelFn() + + waitForNavCh, waitForNavCancel := createWaitForEventHandler(timeoutCtx, f, []string{EventFrameNavigation}, + func(data interface{}) bool { return waitForNavHandler(data, getDocID) }) + defer waitForNavCancel() // Remove event handler + + waitForLifecycleCh, waitForLifecycleCancel := createWaitForEventHandler(timeoutCtx, + f, []string{EventFrameAddLifecycle}, func(data interface{}) bool { + ev, _ := data.(LifecycleEvent) + return ev == opts.WaitUntil + }) + defer waitForLifecycleCancel() + + var event *NavigationEvent + select { + case <-timeoutCtx.Done(): + if errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { + k6Throw(f.ctx, "waitForNavigation timed out after %s", opts.Timeout) + } + // ignore: the extension is shutting down + f.logger.Warnf("Frame:waitForNavigation:waitForNav<-timeoutCtx.Done", + "furl:%s err:%v", f.URL(), ctx.Err()) + return nil + case data := <-waitForNavCh: + event, _ = data.(*NavigationEvent) + } + + if event.newDocument == nil { + f.logger.Debugf("Frame:waitForNavigation", + "furl:%s - event.newDocument is nil", f.URL()) + // In case of navigation within the same document (e.g. via an anchor + // link or the History API), there is no new document and a + // LifecycleEvent will not be emitted, so we don't need to wait for it. + return nil + } + + if f.hasSubtreeLifecycleEventFired(opts.WaitUntil) { + f.logger.Debugf("Frame:waitForNavigation", + "furl:%s fid:%s hasSubtreeLifecycleEventFired:true", f.URL(), f.ID()) + + select { + case <-timeoutCtx.Done(): + if errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { + k6Throw(f.ctx, "wait for navigation timed out waiting for %q after %s", + opts.WaitUntil, opts.Timeout) + } + case <-waitForLifecycleCh: + } + } + + var ( + req = event.newDocument.request + resp api.Response + ) + if req != nil { + resp = req.Response() + } + + return resp } // WaitForSelector waits for the given selector to match the waiting criteria. diff --git a/common/frame_manager.go b/common/frame_manager.go index eed77d5bb..7686a019b 100644 --- a/common/frame_manager.go +++ b/common/frame_manager.go @@ -24,15 +24,11 @@ import ( "context" "errors" "fmt" - "strings" "sync" "sync/atomic" - "time" "github.com/chromedp/cdproto/cdp" "github.com/chromedp/cdproto/network" - "github.com/dop251/goja" - k6common "go.k6.io/k6/js/common" "github.com/grafana/xk6-browser/api" ) @@ -575,125 +571,6 @@ func (m *FrameManager) setMainFrame(f *Frame) { m.mainFrame = f } -// NavigateFrame will navigate specified frame to specified URL. -func (m *FrameManager) NavigateFrame(frame *Frame, url string, opts goja.Value) api.Response { - var ( - fmid = m.ID() - fid = frame.ID() - furl = frame.URL() - ) - m.logger.Debugf("FrameManager:NavigateFrame", - "fmid:%d fid:%v furl:%s url:%s", fmid, fid, furl, url) - defer m.logger.Debugf("FrameManager:NavigateFrame:return", - "fmid:%d fid:%v furl:%s url:%s", fmid, fid, furl, url) - - rt := k6common.GetRuntime(m.ctx) - netMgr := m.page.mainFrameSession.getNetworkManager() - defaultReferer := netMgr.extraHTTPHeaders["referer"] - parsedOpts := NewFrameGotoOptions(defaultReferer, time.Duration(m.timeoutSettings.navigationTimeout())*time.Second) - if err := parsedOpts.Parse(m.ctx, opts); err != nil { - k6common.Throw(rt, fmt.Errorf("failed parsing options: %w", err)) - } - - timeoutCtx, timeoutCancelFn := context.WithTimeout(m.ctx, parsedOpts.Timeout) - defer timeoutCancelFn() - - chSameDoc, evCancelFn := createWaitForEventHandler(timeoutCtx, frame, []string{EventFrameNavigation}, func(data interface{}) bool { - return data.(*NavigationEvent).newDocument == nil - }) - defer evCancelFn() // Remove event handler - - chWaitUntilCh, evCancelFn2 := createWaitForEventHandler(timeoutCtx, frame, []string{EventFrameAddLifecycle}, func(data interface{}) bool { - return data.(LifecycleEvent) == parsedOpts.WaitUntil - }) - defer evCancelFn2() // Remove event handler - - fs := frame.page.getFrameSession(cdp.FrameID(frame.ID())) - if fs == nil { - m.logger.Debugf("FrameManager:NavigateFrame", - "fmid:%d fid:%v furl:%s url:%s fs:nil", - fmid, fid, furl, url) - - // Attaching an iframe to an existing page doesn't seem to trigger a "Target.attachedToTarget" event - // from the browser even when "Target.setAutoAttach" is true. If this is the case fallback to the - // main frame's session. - fs = frame.page.mainFrameSession - } - newDocumentID, err := fs.navigateFrame(frame, url, parsedOpts.Referer) - if err != nil { - k6common.Throw(rt, err) - } - - var event *NavigationEvent - if newDocumentID != "" { - m.logger.Debugf("FrameManager:NavigateFrame", - "fmid:%d fid:%v furl:%s url:%s newDocID:%s", - fmid, fid, furl, url, newDocumentID) - - data, err := waitForEvent(m.ctx, frame, []string{EventFrameNavigation}, func(data interface{}) bool { - ev := data.(*NavigationEvent) - - // We are interested either in this specific document, or any other document that - // did commit and replaced the expected document. - if ev.newDocument != nil && (ev.newDocument.documentID == newDocumentID || ev.err == nil) { - return true - } - return false - }, parsedOpts.Timeout) - if err != nil { - k6common.Throw(rt, err) - } - - event = data.(*NavigationEvent) - if event.newDocument.documentID != newDocumentID { - m.logger.Debugf("FrameManager:NavigateFrame:interrupted", - "fmid:%d fid:%v furl:%s url:%s docID:%s newDocID:%s", - fmid, fid, furl, url, event.newDocument.documentID, newDocumentID) - } else if event.err != nil && - // TODO: A more graceful way of avoiding Throw()? - !(netMgr.userReqInterceptionEnabled && - strings.Contains(event.err.Error(), "ERR_BLOCKED_BY_CLIENT")) { - k6common.Throw(rt, event.err) - } - } else { - m.logger.Debugf("FrameManager:NavigateFrame", - "fmid:%d fid:%v furl:%s url:%s newDocID:0", - fmid, fid, furl, url) - - select { - case <-timeoutCtx.Done(): - if timeoutCtx.Err() == context.DeadlineExceeded { - k6common.Throw(rt, ErrTimedOut) - } - case data := <-chSameDoc: - event = data.(*NavigationEvent) - } - } - - if !frame.hasSubtreeLifecycleEventFired(parsedOpts.WaitUntil) { - m.logger.Debugf("FrameManager:NavigateFrame", - "fmid:%d fid:%v furl:%s url:%s hasSubtreeLifecycleEventFired:false", - fmid, fid, furl, url) - - select { - case <-timeoutCtx.Done(): - if timeoutCtx.Err() == context.DeadlineExceeded { - k6common.Throw(rt, ErrTimedOut) - } - case <-chWaitUntilCh: - } - } - - var resp *Response - if event.newDocument != nil { - req := event.newDocument.request - if req != nil && req.response != nil { - resp = req.response - } - } - return resp -} - // Page returns the page that this frame manager belongs to. func (m *FrameManager) Page() api.Page { if m.page != nil { @@ -702,63 +579,6 @@ func (m *FrameManager) Page() api.Page { return nil } -// WaitForFrameNavigation waits for the given navigation lifecycle event to happen. -func (m *FrameManager) WaitForFrameNavigation(frame *Frame, opts goja.Value) api.Response { - m.logger.Debugf("FrameManager:WaitForFrameNavigation", - "fmid:%d fid:%s furl:%s", - m.ID(), frame.ID(), frame.URL()) - defer m.logger.Debugf("FrameManager:WaitForFrameNavigation:return", - "fmid:%d fid:%s furl:%s", - m.ID(), frame.ID(), frame.URL()) - - parsedOpts := NewFrameWaitForNavigationOptions(time.Duration(m.timeoutSettings.timeout()) * time.Second) - if err := parsedOpts.Parse(m.ctx, opts); err != nil { - k6Throw(m.ctx, "cannot parse waitForNavigation options: %v", err) - } - - ch, evCancelFn := createWaitForEventHandler(m.ctx, frame, []string{EventFrameNavigation}, - func(data interface{}) bool { - return true // Both successful and failed navigations are considered - }) - defer evCancelFn() // Remove event handler - - var event *NavigationEvent - select { - case <-m.ctx.Done(): - // ignore: the extension is shutting down - m.logger.Warnf("FrameManager:WaitForFrameNavigation:<-ctx.Done", - "fmid:%d furl:%s err:%v", - m.ID(), frame.URL(), m.ctx.Err()) - return nil - case <-time.After(parsedOpts.Timeout): - k6Throw(m.ctx, "waitForFrameNavigation timed out after %s", parsedOpts.Timeout) - case data := <-ch: - event = data.(*NavigationEvent) - } - - if event.newDocument == nil { - // In case of navigation within the same document (e.g. via an anchor - // link or the History API), there is no new document and a - // LifecycleEvent will not be fired, so we don't need to wait for it. - return nil - } - - if frame.hasSubtreeLifecycleEventFired(parsedOpts.WaitUntil) { - m.logger.Debugf("FrameManager:WaitForFrameNavigation", - "fmid:%d furl:%s hasSubtreeLifecycleEventFired:true", - m.ID(), frame.URL()) - - _, err := waitForEvent(m.ctx, frame, []string{EventFrameAddLifecycle}, func(data interface{}) bool { - return data.(LifecycleEvent) == parsedOpts.WaitUntil - }, parsedOpts.Timeout) - if err != nil { - k6Throw(m.ctx, "waitForFrameNavigation cannot wait for event (EventFrameAddLifecycle): %v", err) - } - } - - return event.newDocument.request.response -} - // ID returns the unique ID of a FrameManager value. func (m *FrameManager) ID() int64 { return atomic.LoadInt64(&m.id)