[Bug]: Page request events are not emitted in order for cached requests

[lefebvree]

Bug description

For the same HTTP request, listeners on Page events request, response, requestfinished are not ensured to be called in that order for cached requests.

This change in behavior appeared in version 10.2.0 likely due to this change in #6735 delegating request event listeners handler to enqueueInterceptAction, even when interception is not enabled. This makes it likely for response or requestfinished event listeners to be called before for very fast requests (observable on cached resources).

Steps to reproduce the problem:

1. Run this code logging the events of a resource on https://www.iana.org/ before and after being cached

const puppeteer = require('puppeteer');

(async () => {
  const browser = await puppeteer.launch();
  const page = await browser.newPage();

  ['request', 'response', 'requestfinished'].forEach(event => page.on(event, request => {
    if (request.url().endsWith('jquery.js')) console.log(request.url(), event);
  }))

  await page.goto('https://www.iana.org/');

  console.log('Reload...');
  await page.reload();

  await browser.close();
})()

request
response
requestfinished
Reload...
response
requestfinished
request

Puppeteer version

13.4.1

Node.js version

16.13.2

npm version

8.1.2

What operating system are you seeing the problem on?

macOS

Relevant log output

No response

[OrKoN]

@benallfree PTAL

[benallfree]

Hi @lefebvree thank you for such a detailed and thorough report.

I am still reviewing, but can you please explain

This makes it likely for response or requestfinished event listeners to be called before for very fast requests (observable on cached resources).

When you say "makes it likely", what exactly about the change in #6735 produces the out-of-order firing of event listeners?

The reason I ask (besides general understanding) is that there are some Chrome Development Protocol bugs that sound similar to your experience which also appeared in the same Puppeteer updates and it appeared that #6735 introduced the problem when actually it was CDP bugs. See #7802 (comment) for more info on that.

[lefebvree]

When you say "makes it likely", what exactly about the change in #6735 produces the out-of-order firing of event listeners?

The reason I ask (besides general understanding) is that there are some Chrome Development Protocol bugs that sound similar to your experience which also appeared in the same Puppeteer updates and it appeared that #6735 introduced the problem when actually it was CDP bugs. See #7802 (comment) for more info on that.

My guess was that calling the event handler asynchronously through _interceptActions add a small delay to its execution, causing it to sometimes fire after the response event for cached requests when request interception is disabled (however it is not 100% consistent).
But you may be right this could be due to the CDP issue you mentioned instead.

[benallfree]

It's possible also that you may be relying on undefined behavior (order of events). The current Puppeteer test suite doesn't seem to cover this case, and I know for sure that CDP does (or did) fire some events out of order due to a bug and that caching is related. You can research all of this starting from that comment above and see if it matches your observations.

If you still feel there is a bug in Puppeteer, would it be possible to write a test case to cover the bug? Then we can discuss solutions in a PR in a more exact fashion.

Thank you for sticking with this if you are able!

[stale]

We're marking this issue as unconfirmed because it has not had recent activity and we weren't able to confirm it yet. It will be closed if no further activity occurs within the next 30 days.

[stale]

We are closing this issue. If the issue still persists in the latest version of Puppeteer, please reopen the issue and update the description. We will try our best to accomodate it!