1852891 - network.responseCompleted can be emitted after the corresponding navigate call resolved

Status: RESOLVED FIXED

(Remote Protocol :: WebDriver BiDi, defect, P2)

Description

[Julian Descottes [:jdescottes]]

While working on the puppeteer sync for Bug 1851438, we spotted an intermittent failure with one of the proxy tests, [proxy.spec] request proxy should respect proxy bypass list.

In this test, we send a navigate command with wait=complete, but the corresponding network.responseCompleted event is sometimes received after the command resolves (and after we received the domContentLoaded/load events).

The puppeteer logic for their goto command assumes that the responseCompleted event has been received before the command resolves, and fails when it's not the case.

I am not sure exactly what causes responseCompleted to be delayed in our case. We normally send it as soon as the response input stream is closed. If we can't get it to be emitted earlier, we could potentially delay resolving the navigate command until the responseCompleted event has been received, but we would still have a wrong ordering when comparing to the browsingContext.domContentLoaded/load events.

Comment 1

[Julian Descottes [:jdescottes]]

Moving to m9, this started appearing in more tests and we can't release something too flaky.

Comment 2

[Julian Descottes [:jdescottes]]

Some updates on my investigations so far.

First of all I no longer have a good test case to reproduce the failure. I used to reproduce it locally from time to time, but I've not been able to get it once since yesterday. Worst, I also can't get the issue on try anymore for the [proxy.spec] request proxy should respect proxy bypass list test.

Regardless, I tried to switch from DevTools' NetworkObserver to using the "stop" event from the ChannelWrapper (ie the same thing which is used by webextensions in WebRequest.sys.mjs). I can see that this "stop" event is emitted before we receive the addResponseContent from DevTools, but since I'm unable to reproduce the issue I can't verify if this is enough to fix it.

Using this event, we actually pass all the bidi network wdspec tests, but that's only because we never assert the responseData size information in too much details. We are supposed to include the response-content-info in the response data, which corresponds to the decoded size of the response body. This should map to the decodedByteSize of nsIHttpChannel, but this value always remains at 0. Talking to :valentin, the reason is that the value is only set when we actually decode the response, but this happens in content processes, whereas we monitor requests in the parent for now. DevTools is bypassing this issue because they read and decode the inputstream directly in the parent process, so they can manually compute this decoded size.

Which means that if we want to use this event, we still need a way to send the decodedByteSize to the parent, which might add some new delay and negate the benefits of using the "stop" event. One proposal from :valentin is to add a new observer notification in content processes which would happen before "stop", as soon as the decoded size is known and which we could send to the parent and which should be guaranteed to arrive before domContentLoaded/load happen.

One thing to keep in mind here, is that for future scenarios we will probably still want to expose the response body, both as information in the event payload but also for interception purposes. And in that case we probably need to go back to the devtools approach of handling the input stream in the parent. So a solution only exposing the decodedByteSize might not be enough.

Another way to approach this is to try to fix the event order on BiDi's side. On top of events, the main reason this is an issue for puppeteer is because the navigate with wait=complete command resolves before the responseCompleted event is emitted. We could focus on this scenario, and make it so that the browsingContext.navigate command waits for the corresponding network request to be complete before resolving.

Comment 3

[Julian Descottes [:jdescottes]]

Attachment: Bug 1852891 - [bidi] Wait for responseCompleted before resolving browsingContext.navigate

Introduce internal events for existing network events and monitor them from browsingContext.navigate to ensure a responseCompleted event
was received before resolving the command.

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

There is an r+ patch which didn't land and no activity in this bug for 2 weeks.
:jdescottes, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit BugBot documentation.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 07/21 - 08/08)]

Julian will have to take a follow-up look when he is back.

Comment 6

[Julian Descottes [:jdescottes]]

Attachment: Bug 1852891 - [bidi] Move browsingContext awaitNavigation navigated.finally to try / finally

Depends on D191609

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/2dce0125eac1
[bidi] Wait for responseCompleted before resolving browsingContext.navigate r=webdriver-reviewers,whimboo
https://hg.mozilla.org/integration/autoland/rev/db1b6937659d
[bidi] Move browsingContext awaitNavigation navigated.finally to try / finally r=webdriver-reviewers,whimboo

Comment 8

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/2dce0125eac1
https://hg.mozilla.org/mozilla-central/rev/db1b6937659d