Similar to bug 1852891 but more related to the browsingContext.domContentLoaded and browsingContext.load events. In some cases the network.responseCompleted event is delayed that much that it is emitted after the mentioned navigation events.

Here is a log which shows this problem:
https://treeherder.mozilla.org/logviewer?job_id=448677650&repo=try&lineNumber=59049-59055

Here a working case:
https://treeherder.mozilla.org/logviewer?job_id=448677648&repo=try&lineNumber=59037-59054

From the headers I can see a "responseEnd":1709070231895330, and the timestamp of the event is 1709070232031. That means there is a delay of 136ms, and the navigation events are getting emitted roughly 20ms earlier.

Puppeteer seems to be pretty strict here with the order of events (if I'm not wrong). This is most likely a new issue since version 21.10.0 due to the navigation refactoring in Puppeteer.

Maybe Alex can give some details.

I can more easily reproduce this issue with a slow running build like debug and running the following tests in a loop (.deflakeOnly):
https://github.com/puppeteer/puppeteer/blob/1250d25e5c20badd3cbb6c8e465aa70c8dabea07/test/src/ignorehttpserrors.spec.ts#L93-L102

Actually the order of the event doesn't seem to be the reason here but something prevents the call to response.ok() to fail with:

Cannot read properties of null (reading 'ok')","stack":"TypeError: Cannot read properties of null (reading 'ok')\n    at Context.<anonymous> (/Users/henrik/code/gecko/remote/test/puppeteer/test/src/ignorehttpserrors.spec.ts:101:21)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)"}]

Here an example of a network.responseCompleted event when it fails:

 0:08.13 pid:39548 1709103855925	RemoteAgent	DEBUG	WebDriverBiDiConnection 00cf5be2-4f45-4029-a46a-8ccd75d81929 <- {"type":"event","method":"network.responseCompleted","params":{"context":"775916fc-b99d-43ce-8333-a2027d3ebb64","isBlocked":false,"navigation":"23535c2a-7d49-4957-8101-112837e6e206","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"localhost:56010"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:125.0) Gecko/20100101 Firefox/125.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":461,"method":"GET","request":"10","timings":{"timeOrigin":0,"requestTime":1709103855612006,"redirectStart":0,"redirectEnd":0,"fetchStart":1709103855619357,"dnsStart":1709103855619357,"dnsEnd":1709103855622228,"connectStart":1709103855622897,"connectEnd":1709103855628007,"tlsStart":1709103855623399,"tlsEnd":1709103855628007,"requestStart":1709103855628059,"responseStart":1709103855628384,"responseEnd":1709103855631118},"url":"https://localhost:56010/empty.html"},"timestamp":1709103855924,"response":{"bodySize":15,"content":{"size":15},"headersSize":175,"url":"https://localhost:56010/empty.html","bytesReceived":190,"fromCache":false,"headers":[{"name":"Cache-Control","value":{"type":"string","value":"no-cache, no-store"}},{"name":"Content-Type","value":{"type":"string","value":"text/html; charset=utf-8"}},{"name":"Date","value":{"type":"string","value":"Wed, 28 Feb 2024 07:04:15 GMT"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Content-Length","value":{"type":"string","value":"15"}}],"mimeType":"text/html;charset=utf-8","protocol":"http/1.1","status":200,"statusText":"OK"}}}

Both status and statusText look fine to me.

The error means that Puppeteer could not find the network request for the navigation.

It is possible that this happens if the network request is not announced before the navigation is over. In this case, Puppeteer has to assume that the navigation has not triggered a network request.

We clearly send out all the related network events before the browsingContext.navigate command returns. I just checked and the referenced navigation id is correct as well. In some cases realms are getting destroyed multiple times, so not sure if this could have an effect?

Something I just noticed is that in case of failures I see the following line:

Skipping already tracked navigation, navigationId: 6a2dd2e1-bb4d-41db-b030-73c8168cfa68

Julian, does that ring a bell? I wonder why this is only logged when a failure happens, and what's the cause of it.

Do you have BiDi events log for the failed run (I have not tried to reproduce so far, I am not sure I have a slow build available)?

(I mean the log from Puppeteer, DEBUG=puppeteer:*)

I've run the test with a debug build and get this Puppeteer output:

 0:07.75 pid:54168 puppeteer:webDriverBiDi:SEND ►{"id":11,"method":"browsingContext.navigate","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","url":"https://localhost:58724/empty.html","wait":"interactive"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"browsingContext.navigationStarted","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","navigation":"1a1bfd48-0155-455e-a10a-160eefbca893","timestamp":1709114469778,"url":"https://localhost:58724/empty.html"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"network.beforeRequestSent","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","isBlocked":false,"navigation":"1a1bfd48-0155-455e-a10a-160eefbca893","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"localhost:58724"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:125.0) Gecko/20100101 Firefox/125.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":461,"method":"GET","request":"9","timings":{"timeOrigin":0,"requestTime":1709114469772106,"redirectStart":0,"redirectEnd":0,"fetchStart":1709114469785073,"dnsStart":1709114469785073,"dnsEnd":1709114469785140,"connectStart":1709114469785327,"connectEnd":1709114469791246,"tlsStart":1709114469785928,"tlsEnd":1709114469791246,"requestStart":1709114469791307,"responseStart":1709114469791792,"responseEnd":0},"url":"https://localhost:58724/empty.html"},"timestamp":1709114469792,"initiator":{"type":"other"}}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"network.responseStarted","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","isBlocked":false,"navigation":"1a1bfd48-0155-455e-a10a-160eefbca893","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"localhost:58724"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:125.0) Gecko/20100101 Firefox/125.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":461,"method":"GET","request":"9","timings":{"timeOrigin":0,"requestTime":1709114469772106,"redirectStart":0,"redirectEnd":0,"fetchStart":1709114469785073,"dnsStart":1709114469785073,"dnsEnd":1709114469785140,"connectStart":1709114469785327,"connectEnd":1709114469791246,"tlsStart":1709114469785928,"tlsEnd":1709114469791246,"requestStart":1709114469791307,"responseStart":1709114469791792,"responseEnd":1709114469794534},"url":"https://localhost:58724/empty.html"},"timestamp":1709114469812,"response":{"bodySize":0,"content":{"size":null},"headersSize":175,"url":"https://localhost:58724/empty.html","bytesReceived":175,"fromCache":false,"headers":[{"name":"Cache-Control","value":{"type":"string","value":"no-cache, no-store"}},{"name":"Content-Type","value":{"type":"string","value":"text/html; charset=utf-8"}},{"name":"Date","value":{"type":"string","value":"Wed, 28 Feb 2024 10:01:09 GMT"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Content-Length","value":{"type":"string","value":"15"}}],"mimeType":"text/html;charset=utf-8","protocol":"http/1.1","status":200,"statusText":"OK"}}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"script.realmDestroyed","params":{"realm":"d2cb5e90-d88c-425c-be6e-6782e115e015"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"script.realmCreated","params":{"realm":"11464413-8784-4229-9727-8e6e1e09e1d6","origin":"null","context":"9972a46e-b536-4700-8fc7-83e52e34f931","type":"window"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"script.realmDestroyed","params":{"realm":"11464413-8784-4229-9727-8e6e1e09e1d6"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"script.realmCreated","params":{"realm":"3fb4800b-536f-457f-a50b-f4659df9427e","origin":"https://localhost:58724","context":"9972a46e-b536-4700-8fc7-83e52e34f931","type":"window"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"browsingContext.domContentLoaded","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","timestamp":1709114470044,"url":"https://localhost:58724/empty.html","navigation":"1a1bfd48-0155-455e-a10a-160eefbca893"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"browsingContext.load","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","timestamp":1709114470046,"url":"https://localhost:58724/empty.html","navigation":"1a1bfd48-0155-455e-a10a-160eefbca893"}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"event","method":"network.responseCompleted","params":{"context":"9972a46e-b536-4700-8fc7-83e52e34f931","isBlocked":false,"navigation":"1a1bfd48-0155-455e-a10a-160eefbca893","redirectCount":0,"request":{"bodySize":null,"cookies":[],"headers":[{"name":"Host","value":{"type":"string","value":"localhost:58724"}},{"name":"User-Agent","value":{"type":"string","value":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:125.0) Gecko/20100101 Firefox/125.0"}},{"name":"Accept","value":{"type":"string","value":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"}},{"name":"Accept-Language","value":{"type":"string","value":"en-US,en;q=0.5"}},{"name":"Accept-Encoding","value":{"type":"string","value":"gzip, deflate, br"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Upgrade-Insecure-Requests","value":{"type":"string","value":"1"}},{"name":"Sec-Fetch-Dest","value":{"type":"string","value":"document"}},{"name":"Sec-Fetch-Mode","value":{"type":"string","value":"navigate"}},{"name":"Sec-Fetch-Site","value":{"type":"string","value":"none"}},{"name":"Sec-Fetch-User","value":{"type":"string","value":"?1"}}],"headersSize":461,"method":"GET","request":"9","timings":{"timeOrigin":0,"requestTime":1709114469772106,"redirectStart":0,"redirectEnd":0,"fetchStart":1709114469776619,"dnsStart":1709114469776619,"dnsEnd":1709114469784709,"connectStart":1709114469785327,"connectEnd":1709114469791246,"tlsStart":1709114469785928,"tlsEnd":1709114469791246,"requestStart":1709114469791307,"responseStart":1709114469791792,"responseEnd":1709114469794534},"url":"https://localhost:58724/empty.html"},"timestamp":1709114470091,"response":{"bodySize":15,"content":{"size":15},"headersSize":175,"url":"https://localhost:58724/empty.html","bytesReceived":190,"fromCache":false,"headers":[{"name":"Cache-Control","value":{"type":"string","value":"no-cache, no-store"}},{"name":"Content-Type","value":{"type":"string","value":"text/html; charset=utf-8"}},{"name":"Date","value":{"type":"string","value":"Wed, 28 Feb 2024 10:01:09 GMT"}},{"name":"Connection","value":{"type":"string","value":"keep-alive"}},{"name":"Content-Length","value":{"type":"string","value":"15"}}],"mimeType":"text/html;charset=utf-8","protocol":"http/1.1","status":200,"statusText":"OK"}}}
 0:07.75 pid:54168 puppeteer:webDriverBiDi:RECV ◀{"type":"success","id":11,"result":{"navigation":"1a1bfd48-0155-455e-a10a-160eefbca893","url":"https://localhost:58724/empty.html"}}

It does look normal, is there an easy way for me to reproduce?

A debug build should hopefully get you going. You can download the DMG from our CI. Just open the link and click the Artifacts and Debugging Tools panel on the black bar, and download the target.dmg - or use this direct link.

As it looks like this is a regression since Puppeteer 22.1.0. With the 22.0.0 release the test passes with a debug build.

So for me the regression starts with the following commit which no longer uses HTML test pages in Quirks mode:
https://github.com/puppeteer/puppeteer/commit/aef584c815571ca8c02b111dd08c27be11562a5f#diff-bc8a5bc94bd1fa378a414a23ab92a8c84842cfa4c1a9eef0c7bbcb6293a0f7a3

Removing <!DOCTYPE html> makes it actually work again with Puppeteer 22.3.0.

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #5)

Something I just noticed is that in case of failures I see the following line:

Skipping already tracked navigation, navigationId: 6a2dd2e1-bb4d-41db-b030-73c8168cfa68

Julian, does that ring a bell? I wonder why this is only logged when a failure happens, and what's the cause of it.

I think I see the same thing on the success logs except the id is different of course:

[963cbcaf-fb26-4e9b-96e4-c729f437eab1] Skipping already tracked navigation, navigationId: 53af27cb-30c4-4dfa-ac08-43df345cac88

This can happen for several reasons (eg if a navigation is first detected because of a beforeRequestSent event), but here it seems we are having a cross group navigation. I imagine we move from about:blank to empty.html. The navigation listeners pickup the navigation for the new browsing context and emit an extra "navigation-started" event which we ignore.

I don't think this is directly related to the failure we are investigating here. Overall, our responseCompleted event is probably emitted a bit late (because we wait for the inputStream to close), so I'm not too surprised we have situations where this event is only emitted after the load event. As you mentioned we already had to fix this explicitly for navigate with wait=complete, maybe we will have to strongly enforce the order(for events and commands) for everything navigation related.

Some more details:

1. Changing the test to use HTTP for loading empty.html will let the test pass
2. Adding more content to empty.html like a CSS rule for external fonts will also allow the test to pass
3. I cannot replicate the issue with empty pages on remote addresses but only via the local HTTPS server by Puppeteer

As discussed with Alex, the test will be marked as flaky for now.

It doesn't seem to work to just disable a single test. As it looks like the same problem manifests for quite some other tests as well:
https://treeherder.mozilla.org/jobs?repo=try&revision=a7c35fb6cff0eb2feaa8b361629a64ab53aaf0c8

I'm attempting to modify the windowglobal-in-root browsingContext module to delay the domContentLoaded/load events until we get responseCompleted (iff the navigation seems linked to network events)

Thanks Julian. We should make sure that this doesn't affect timing, means that the timestamp property of the event should be the one when we actually received DOMContentLoaded or load internally. Otherwise this change would negatively affect the performance tests / HAR recording.

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #17)

Thanks Julian. We should make sure that this doesn't affect timing, means that the timestamp property of the event should be the one when we actually received DOMContentLoaded or load internally. Otherwise this change would negatively affect the performance tests / HAR recording.

Very good point. The timestamp is collected in the content process when we detect the underlying event, so that should not negatively impact those tests.

As discussed today, we might rather go for a puppeteer fix to unblock the current sync.

I will still upload my patch here but let's discuss it a bit more before we commit and review this.

For info I was trying to create a wdspec test to reproduce the issue, but I have not been successful so far. I always seem to get the events in the expected order, whether the test page uses quirks mode or not.

The test I tried to add can be seen at https://treeherder.mozilla.org/jobs?repo=try&revision=0bb74abc044a6a442965c2dc464889aa3fbfea8e&selectedTaskRun=JeWqXLiMSiqOb2ptI227HA.0