Request.frame is sometimes nil

[imiric]

Sometimes when we create a new Request here:

xk6-browser/common/network_manager.go

Lines 342 to 350 in 9882ab5

	var frame *Frame = nil
	if event.FrameID != "" {
	frame = m.frameManager.getFrameByID(event.FrameID)
	}
	if frame == nil {
	m.logger.Debugf("NetworkManager", "frame is nil")
	}
	req, err := NewRequest(m.ctx, event, frame, redirectChain, interceptionID, m.userReqInterceptionEnabled)

... we get a nil Frame pointer from FrameManager.getFrameByID().

The logic of how m.frames is changed is a bit convoluted, as we delete frames in a couple of places:

• xk6-browser/common/frame_manager.go

  Line 185 in 9882ab5

  delete(m.frames, cdp.FrameID(frame.ID()))

• xk6-browser/common/frame_manager.go

  Line 295 in 9882ab5

  delete(m.frames, cdp.FrameID(frame.ID()))

We added some debugging information in 0451efb so we can see when it happens, but there's likely a synchronization bug here that we need to address so that anything that needs a Frame reference (e.g. when getting the session through it for Response.fetchBody() (which we could possibly store directly on Response to avoid resolving the reference chain?)) can run before we actually delete the Frame.

[imiric]

Some more info about this: from testing with the script in #49, when we get a nil Frame in NetworkManager.onRequest() it's because event.FrameID == "", i.e. there's no Frame associated to the RequestWillBeSent event to lookup. In all cases these are preflight/OPTIONS requests, which typically don't have a body anyway, though this is not strictly forbidden by the spec. So if the responses have Content-Length we would emit metrics for them fine and won't rely on Response.fetchBody()/CDP.

That said, the reason fetchBody() fails so often is because calling network.GetResponseBody() shouldn't be done on the ResponseReceived event, but on the LoadingFinished one. See ChromeDevTools/devtools-protocol#44 (comment).

So the fix I'm currently working on involves emitting metrics for Response only in the LoadingFinished handler, which does produce less error fetching response body warnings, but I'm running into an issue where sometimes we don't get a ResponseReceived event before we get LoadingFinished, so the Response we set on the Request is nil. Not sure why this happens, the flow should be RequestWillBeSent -> ResponseReceived -> LoadingFinished.

An alternative to using network.GetResponseBody() and len(r.body) to emit data_received metrics could be to use EventLoadingFinished.EncodedDataLength. This seems like it would be more reliable, yet I've seen cases where this is 0.0 and len(r.body) > 0. So... 🤷‍♂️ I'll have to look deeper into this.

[inancgumus]

This is in the review queue. You didn't request me to review this yet but should I add my review to this? @imiric

[imiric]

The PR for this is #117. It's still a draft because of the race condition it introduces, which I'm not sure how to fix yet, and well, other issues have come up in the meantime.

[imiric]

I think we can close this. As explained above, Frame being nil is a valid state, and we no longer panic because of it. After #117 it's being logged with more detail, and fetchBody() is more reliable, so we shouldn't see it as often.

WDYT @inancgumus?

[inancgumus]

👍