Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Request interception hanging forever #7475

Closed
marvinhagemeister opened this issue Aug 6, 2021 · 40 comments
Closed

Request interception hanging forever #7475

marvinhagemeister opened this issue Aug 6, 2021 · 40 comments
Assignees

Comments

@marvinhagemeister
Copy link
Contributor

Steps to reproduce

Tell us about your environment:

What steps will reproduce the problem?

The issue can be reproduced with the following snippet:

const puppeteer = require('puppeteer');

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

    page.on('request', request => request.continue());
    await page.setRequestInterception(true);

    await page.goto('https://login.tonies.com/legals/terms-of-service');

    console.log('SUCCESS');
    await browser.close();
})();
  1. Run above snippet -> never prints "SUCCESS"

Note: When run in headful mode via devtools: true it fails not as consistently anymore, but still fails from time to time.

From the past hours debugging this, it seems to be caused by a font-face request pending forever. This issue seems similar to #6696 .

What is the expected result?

Requests should not hang.

What happens instead?

A request for a font never resolves, which leads to the load event never being fired. This leads to puppeteer throwing a timeout error.

@marvinhagemeister
Copy link
Contributor Author

Went through the CDP messages and have some more info: Whenever a request hangs, there are two Fetch.requestPaused messages for the same request, but with different request ids.

puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSent","params":{"requestId":"30096.7", ... "request":{"url":"https://login.tonies.com/static/media/bello.0f00c622.woff2", ... } +0ms
# ...
puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-10.0","request":{"url":"https://login.tonies.com/static/media/bello.0f00c622.woff2", ... "networkId":"30096.7"}} +0ms
# ...
puppeteer:protocol:SEND ► {..., "method":"Fetch.continueRequest","params":{"requestId":"interception-job-11.0"},"id":29} +19ms
# ...
puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-13.0","request":{"url":"https://login.tonies.com/static/media/bello.0f00c622.woff2", ... "networkId":"30096.7"},} +1ms

Notice the different request ids: "interception-job-10.0" vs "interception-job-13.0". There is only one "Network.requestWillBeSent" event for this url, but somehow we get another "Fetch.requestPaused" event after we've continued the original request. And that's where puppeteer hangs, because it doesn't send the Fetch.continueRequest event back.

I'm not sure if this is an issue with puppeteer or with Chromium itself. As someone with not much knowledge of the CDP protocol it looks like Chromium should never send the second "Fetch.requestPaused" for the same request.

@marvinhagemeister
Copy link
Contributor Author

This issue doesn't occur when caching is disabled via await page.setCacheEnabled(false);.

Ah, it seems like there is a corresponding CR bug: https://bugs.chromium.org/p/chromium/issues/detail?id=1196004 . The mentioned --disable-feature=WebFontsCacheAwareTimeoutAdaption flag doesn't workaround this problem for me though. Only disabling caching does.

@marvinhagemeister
Copy link
Contributor Author

Just went through a bunch of different puppeteer versions and weirdly the issue starts to occur for me starting with 10.0.0. It doesn't happen as often and I have to repeatedly call the snippet in the original post a few times until a font request hangs. Presumably it's hitting a race condition somewhere. It's weird because 10.0.0 supposedly contains the fix for this.

@Androbin
Copy link
Contributor

Androbin commented Aug 8, 2021

The fix landed in 10.2.0

@Androbin
Copy link
Contributor

Androbin commented Aug 8, 2021

I can't reproduce the issue with the following environment:

  • Puppeteer version: 10.2.0
  • Platform / OS version: Ubuntu 20.04.2 LTS
  • Node.js version: 16.6.1

I'm using the script provided

@dekelev
Copy link

dekelev commented Sep 27, 2021

v10.2.0 broke the page.setRequestInterception(true) flow for me and probably for all the puppeteer plugins that are using it. I reverted to v10.1.0, where it still works. The page.on('request', request => {}) callback is not triggered at all in v10.2.0 and above (I also tried with v10.3.0 & v10.4.0). I am using it to detect a page redirect and abort the request.

@mmoutonn
Copy link

This bug is still present on v11.0.0

@benallfree
Copy link
Contributor

@dekelev Do you have any more information such as Puppeteer tickets or reproductions? I am the author of Cooperative Request Intercepts and I've heard a few people report similar issues but nobody has ever repro'd anything for me #6735

@benallfree
Copy link
Contributor

@mmoutonn Can you send some code to repro the issue?

@benallfree
Copy link
Contributor

benallfree commented Nov 23, 2021

The fix landed in 10.2.0

@Androbin Do you have a link to the exact PR that fixed this issue?

@Androbin
Copy link
Contributor

The issue of request interception with caching failing when loading stylesheet-initiated fonts was fixed in #7060, accompanied by a unit test. If you can modify the unit test to be failing again, I'd be happy to take a look. Also see #7038 @starrify for an excellent analysis of the underlying issue.

@benallfree
Copy link
Contributor

@Androbin Thank you. At first glance it doesn't appear that it is related to or caused by the work in #6735, so I'll exit this ticket :)

@hemanthreddyk
Copy link

hemanthreddyk commented Nov 23, 2021

Noticing similar issue in

  • Puppeteer version: 10.4.0
  • Platform / OS version: Alpine Linux 3.13.5
  • Chromium 93.0.4577.82
  • Node.js version: 14.18.0

Requests to fetch fonts from the CDN never completes and eventually page.goto hits timeout duration.
This issue doesn't occur when caching is disabled via await page.setCacheEnabled(false).

  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Book.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Book.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Regular.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Medium-d74eac43c78bd5852478998ce63dceb3.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Bold.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Regular.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Medium-0a6358ad049cd2e4627ceb672d1b7a8d.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Bold.woff": {
    "request": 1,
    "response": 0
  }
}

@atikenny
Copy link

Have the same issue.

After some debugging, it seems to be only hanging for certain URLs and in headful mode. In my case, https://www.google.com breaks but https://www.example.com does NOT.
According to the debug logs, google.com sends a Network.requestWillBeSentExtraInfo message as well, which also gets paused and is never resolved.

Debug logs

Headful mode

puppeteer:protocol:SEND ► {"sessionId":"5944062C119C093327DF7CEEFD908B73","method":"Page.navigate","params":{"url":"https://www.google.com","frameId":"E8CD80D43F6A23389750A4CC3B4E223D"},"id":18} +2ms
puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSent","params":{"requestId":"4AC6D40EC03FFF918C930C480E2CEBD7","loaderId":"4AC6D40EC03FFF918C930C480E2CEBD7","documentURL":"https://www.google.com/","request":{"url":"https://www.google.com/","method":"GET","headers":{"sec-ch-ua":"\"Chromium\";v=\"93\", \" Not;A Brand\";v=\"99\"","sec-ch-ua-mobile":"?0","sec-ch-ua-platform":"\"macOS\"","Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.0 Safari/537.36"},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin","isSameSite":true},"timestamp":945575.611421,"wallTime":1637897800.032329,"initiator":{"type":"other"},"type":"Document","frameId":"E8CD80D43F6A23389750A4CC3B4E223D","hasUserGesture":false},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +5ms
puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-1.0","request":{"url":"https://www.google.com/","method":"GET","headers":{"sec-ch-ua":"\"Chromium\";v=\"93\", \" Not;A Brand\";v=\"99\"","sec-ch-ua-mobile":"?0","sec-ch-ua-platform":"\"macOS\"","Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.0 Safari/537.36","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"E8CD80D43F6A23389750A4CC3B4E223D","resourceType":"Document","networkId":"4AC6D40EC03FFF918C930C480E2CEBD7"},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +3ms
puppeteer:protocol:SEND ► {"sessionId":"5944062C119C093327DF7CEEFD908B73","method":"Fetch.continueRequest","params":{"requestId":"interception-job-1.0"},"id":19} +8ms
puppeteer:protocol:RECV ◀ {"id":19,"result":{},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +2ms
puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSentExtraInfo","params":{"requestId":"4AC6D40EC03FFF918C930C480E2CEBD7","associatedCookies":[],"headers":{":method":"GET",":authority":"www.google.com",":scheme":"https",":path":"/","sec-ch-ua":"\"Chromium\";v=\"93\", \" Not;A Brand\";v=\"99\"","sec-ch-ua-mobile":"?0","sec-ch-ua-platform":"\"macOS\"","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.0 Safari/537.36","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9","x-client-data":"CNflygE=","sec-fetch-site":"none","sec-fetch-mode":"navigate","sec-fetch-user":"?1","sec-fetch-dest":"document","accept-encoding":"gzip, deflate, br","accept-language":"en-GB,en-US;q=0.9,en;q=0.8"}},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +2ms
puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-2.0","request":{"url":"https://www.google.com/","method":"GET","headers":{"sec-ch-ua":"\"Chromium\";v=\"93\", \" Not;A Brand\";v=\"99\"","sec-ch-ua-mobile":"?0","sec-ch-ua-platform":"\"macOS\"","Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/93.0.4577.0 Safari/537.36","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9","sec-ch-ua-full-version":"\"93.0.4577.0\"","sec-ch-ua-arch":"\"arm\"","sec-ch-ua-platform-version":"\"11.6.0\"","sec-ch-ua-model":"\"\""},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"E8CD80D43F6A23389750A4CC3B4E223D","resourceType":"Document","networkId":"4AC6D40EC03FFF918C930C480E2CEBD7"},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +0ms
puppeteer:protocol:RECV ◀ {"method":"Page.lifecycleEvent","params":{"frameId":"E8CD80D43F6A23389750A4CC3B4E223D","loaderId":"08029F9CC98CEFFD8C035E0E9B962909","name":"networkAlmostIdle","timestamp":945575.580685},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +949ms
puppeteer:protocol:RECV ◀ {"method":"Page.lifecycleEvent","params":{"frameId":"E8CD80D43F6A23389750A4CC3B4E223D","loaderId":"08029F9CC98CEFFD8C035E0E9B962909","name":"networkIdle","timestamp":945575.580685},"sessionId":"5944062C119C093327DF7CEEFD908B73"} +2ms

Headless mode

puppeteer:protocol:SEND ► {"sessionId":"DEE22C51C2B89B406FE668A6039F85A1","method":"Page.navigate","params":{"url":"https://www.google.com","frameId":"3430EE99FA14819E2456BC4FD2106979"},"id":18} +1ms
puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSent","params":{"requestId":"2B0EA69F0B94FF17FE643A3CDDE190D9","loaderId":"2B0EA69F0B94FF17FE643A3CDDE190D9","documentURL":"https://www.google.com/","request":{"url":"https://www.google.com/","method":"GET","headers":{"Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.0 Safari/537.36"},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin","isSameSite":true},"timestamp":945701.85853,"wallTime":1637897926.280562,"initiator":{"type":"other"},"type":"Document","frameId":"3430EE99FA14819E2456BC4FD2106979","hasUserGesture":false},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +3ms
puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-1.0","request":{"url":"https://www.google.com/","method":"GET","headers":{"Upgrade-Insecure-Requests":"1","User-Agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.0 Safari/537.36","Accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"3430EE99FA14819E2456BC4FD2106979","resourceType":"Document","networkId":"2B0EA69F0B94FF17FE643A3CDDE190D9"},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +19ms
puppeteer:protocol:SEND ► {"sessionId":"DEE22C51C2B89B406FE668A6039F85A1","method":"Fetch.continueRequest","params":{"requestId":"interception-job-1.0"},"id":19} +23ms
puppeteer:protocol:RECV ◀ {"id":19,"result":{},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +2ms
puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSentExtraInfo","params":{"requestId":"2B0EA69F0B94FF17FE643A3CDDE190D9","associatedCookies":[],"headers":{":method":"GET",":authority":"www.google.com",":scheme":"https",":path":"/","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.0 Safari/537.36","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9","sec-fetch-site":"none","sec-fetch-mode":"navigate","sec-fetch-user":"?1","sec-fetch-dest":"document","accept-encoding":"gzip, deflate, br","accept-language":"en-US"}},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +74ms
puppeteer:protocol:RECV ◀ {"method":"Network.responseReceivedExtraInfo","params":{"requestId":"2B0EA69F0B94FF17FE643A3CDDE190D9","blockedCookies":[],"headers":{"date":"Fri, 26 Nov 2021 03:38:46 GMT","expires":"-1","cache-control":"private, max-age=0","content-type":"text/html; charset=UTF-8","bfcache-opt-in":"unload","p3p":"CP=\"This is not a P3P policy! See g.co/p3phelp for more info.\"","content-encoding":"gzip","server":"gws","content-length":"54397","x-xss-protection":"0","x-frame-options":"SAMEORIGIN","set-cookie":"CONSENT=PENDING+177; expires=Sun, 26-Nov-2023 03:38:46 GMT; path=/; domain=.google.com; Secure","alt-svc":"h3=\":443\"; ma=2592000,h3-29=\":443\"; ma=2592000,h3-Q050=\":443\"; ma=2592000,h3-Q046=\":443\"; ma=2592000,h3-Q043=\":443\"; ma=2592000,quic=\":443\"; ma=2592000; v=\"46,43\""},"resourceIPAddressSpace":"Public"},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +104ms
puppeteer:protocol:RECV ◀ {"method":"Network.responseReceived","params":{"requestId":"2B0EA69F0B94FF17FE643A3CDDE190D9","loaderId":"2B0EA69F0B94FF17FE643A3CDDE190D9","timestamp":945702.059863,"type":"Document","response":{"url":"https://www.google.com/","status":200,"statusText":"","headers":{"date":"Fri, 26 Nov 2021 03:38:46 GMT","expires":"-1","cache-control":"private, max-age=0","content-type":"text/html; charset=UTF-8","bfcache-opt-in":"unload","p3p":"CP=\"This is not a P3P policy! See g.co/p3phelp for more info.\"","content-encoding":"gzip","server":"gws","content-length":"54397","x-xss-protection":"0","x-frame-options":"SAMEORIGIN","set-cookie":"CONSENT=PENDING+177; expires=Sun, 26-Nov-2023 03:38:46 GMT; path=/; domain=.google.com; Secure","alt-svc":"h3=\":443\"; ma=2592000,h3-29=\":443\"; ma=2592000,h3-Q050=\":443\"; ma=2592000,h3-Q046=\":443\"; ma=2592000,h3-Q043=\":443\"; ma=2592000,quic=\":443\"; ma=2592000; v=\"46,43\""},"mimeType":"text/html","requestHeaders":{":method":"GET",":authority":"www.google.com",":scheme":"https",":path":"/","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.0 Safari/537.36","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9","sec-fetch-site":"none","sec-fetch-mode":"navigate","sec-fetch-user":"?1","sec-fetch-dest":"document","accept-encoding":"gzip, deflate, br","accept-language":"en-US"},"connectionReused":false,"connectionId":12,"remoteIPAddress":"[2a00:1450:400d:80a::2004]","remotePort":443,"fromDiskCache":false,"fromServiceWorker":false,"fromPrefetchCache":false,"encodedDataLength":416,"timing":{"requestTime":945701.880997,"proxyStart":-1,"proxyEnd":-1,"dnsStart":1.18,"dnsEnd":14.823,"connectStart":14.823,"connectEnd":71.546,"sslStart":24.43,"sslEnd":71.519,"workerStart":-1,"workerReady":-1,"workerFetchStart":-1,"workerRespondWithSettled":-1,"sendStart":72.025,"sendEnd":72.188,"pushStart":0,"pushEnd":0,"receiveHeadersEnd":176.405},"responseTime":1.637897926478978e+12,"protocol":"h2","securityState":"secure","securityDetails":{"protocol":"TLS 1.3","keyExchange":"","keyExchangeGroup":"CECPQ2","cipher":"AES_256_GCM","certificateId":0,"subjectName":"www.google.com","sanList":["www.google.com"],"issuer":"GTS CA 1C3","validFrom":1635736776,"validTo":1642994375,"signedCertificateTimestampList":[],"certificateTransparencyCompliance":"unknown"}},"frameId":"3430EE99FA14819E2456BC4FD2106979"},"sessionId":"DEE22C51C2B89B406FE668A6039F85A1"} +2ms

Environment

Puppeteer version: >= 10.0.0
OS: MacOS Big Sur 11.6
Node: 16.13.0

Script to reproduce the issue

const puppeteer = require('puppeteer');

(async () => {
  const browser = await puppeteer.launch({ headless: false });
  const page = await browser.newPage();
  await page.setRequestInterception(true);
  page.on('request', (interceptedRequest) => {
    interceptedRequest.continue();
  });
  await page.goto('https://www.google.com');
  await browser.close();
})();

Workaround

Reverting back to Puppeteer 9.1.1
OR
using headless mode.

@razorman8669
Copy link

@benallfree I'm also having issues with puppeteer 10.0.2 where it hangs until the timeout. reverting back to 10.0.1 doesn't have the problem. I pinpointed it to the cooperative requests PR, however, I haven't figured out exactly why it's breaking my code as I only have one request interceptor. Our codebase is very large so it might take a bit to figure out a basic repro scenario, but I can definitely confirm that 10.0.2 does indeed break our codebase and 10.0.1 does NOT.

@benallfree
Copy link
Contributor

@razorman8669 Do you mean 10.2.0? Cooperative requests didn't land til 10.2.0, so if you are seeing an issue on earlier versions (10.0.2/10.0.1) it likely is not related. If you can get a snippet to repro that would be super helpful. In the mean time, I'll use the original snippet in this ticket and see if I can repro it on main.

@razorman8669
Copy link

Yes, i meant 10.2.0 (not 10.0.2). Sorry for the confusion

@benallfree
Copy link
Contributor

benallfree commented Nov 26, 2021

@atikenny I confirm the same thing exactly. @razorman8669 Definitely not related to #6735.

According to git bisect:

Bad commit: f863f4b
Previous commit (good): 2c9ff4f

Changing from Chromium 869685 to 884014 is the culprit.

All you have to do in f863f4b is update ./src/revisions.ts back to 869685 and it works again.

export const PUPPETEER_REVISIONS: Revisions = {
  chromium: '884014', // BAD
  firefox: 'latest',
};

@jschfflr This one comes from #7288, any thoughts?

@benallfree
Copy link
Contributor

benallfree commented Nov 26, 2021

Update for everyone -

The issue is Fetch.requestPaused gets fired twice by CDP even though only one Network.requestWillBeSent is fired.

The way NetworkManger is written, it assumes a 1:1 interaction between the two events, but that is not true. See #7038 (comment),.

I think #6996 (comment) has introduced some complexity, looking into it further.

@hemanthreddyk
Copy link

Noticing similar issue in

  • Puppeteer version: 10.4.0
  • Platform / OS version: Alpine Linux 3.13.5
  • Chromium 93.0.4577.82
  • Node.js version: 14.18.0

Requests to fetch fonts from the CDN never completes and eventually page.goto hits timeout duration. This issue doesn't occur when caching is disabled via await page.setCacheEnabled(false).

  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Book.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Book.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Regular.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Medium-d74eac43c78bd5852478998ce63dceb3.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Bold.woff2": {
    "request": 2,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Regular.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Medium-0a6358ad049cd2e4627ceb672d1b7a8d.woff": {
    "request": 1,
    "response": 0
  },
  "https://d7ky4nj0uhwst.cloudfront.net/CircularXXWeb-Bold.woff": {
    "request": 1,
    "response": 0
  }
}

In my case we are seeing CORS issue while trying to fetch the fonts. Even if this request fails, pdf should be generated with some other fallback font.
But when request interception + caching is enabled I am noticing that page load is never ending and ultimately leading to timeout

request interception + caching disabled -- Successfully generates a PDF

2021-11-26T09:52:01.676Z puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSent","params":{"requestId":"51.12","loaderId":"086513337FF2FB4966B4F2157EF15EC4","documentURL":"http://router/view/b9899918fcaf44fdaca9409b81e640bf?Context=US","request":{"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","method":"GET","headers":{"sec-ch-ua":"","Referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css","Origin":"http://router","sec-ch-ua-mobile":"?0","User-Agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":""},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin","isSameSite":false},"timestamp":13652.11173,"wallTime":1637920321.675487,"initiator":{"type":"parser","url":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},"type":"Font","frameId":"7357F49A31DE71B7442BEDC81E9890D7","hasUserGesture":false},"sessionId":"00F54722D3672580D2BD0F5041BAB404"}
2021-11-26T09:52:01.677Z puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-41.0","request":{"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","method":"GET","headers":{"sec-ch-ua":"","Origin":"http://router","sec-ch-ua-mobile":"?0","User-Agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":"","Accept":"*/*","Referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"7357F49A31DE71B7442BEDC81E9890D7","resourceType":"Font","networkId":"51.12"},"sessionId":"00F54722D3672580D2BD0F5041BAB404"}
2021-11-26T09:52:01.678Z puppeteer:protocol:SEND ► {"sessionId":"00F54722D3672580D2BD0F5041BAB404","method":"Fetch.continueRequest","params":{"requestId":"interception-job-41.0","url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","headers":[{"name":"sec-ch-ua","value":""},{"name":"referer","value":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},{"name":"origin","value":"http://router"},{"name":"sec-ch-ua-mobile","value":"?0"},{"name":"user-agent","value":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36"},{"name":"sec-ch-ua-platform","value":""}]},"id":64}
2021-11-26T09:52:01.679Z puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSentExtraInfo","params":{"requestId":"51.12","associatedCookies":[],"headers":{":method":"GET",":authority":"int-us-east-1-scnext.flowbrite-statics.net",":scheme":"https",":path":"/CircularXXWeb-Book.woff","pragma":"no-cache","cache-control":"no-cache","sec-ch-ua":"","origin":"http://router","sec-ch-ua-mobile":"?0","user-agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":"","sec-fetch-site":"cross-site","sec-fetch-mode":"cors","sec-fetch-dest":"font","referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css","accept-encoding":"gzip, deflate, br","accept-language":"en-US"},"clientSecurityState":{"initiatorIsSecureContext":false,"initiatorIPAddressSpace":"Private","privateNetworkRequestPolicy":"WarnFromInsecureToMorePrivate"}},"sessionId":"00F54722D3672580D2BD0F5041BAB404"}
2021-11-26T09:52:01.684Z puppeteer:protocol:RECV ◀ {"method":"Log.entryAdded","params":{"entry":{"source":"javascript","level":"error","text":"Access to font at 'https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff' from origin 'http://router' has been blocked by CORS policy: No 'Access-Control-Allow-Origin' header is present on the requested resource.","timestamp":1.637920321683895e+12,"url":"http://router/view/b9899918fcaf44fdaca9409b81e640bf?Context=US"}},"sessionId":"00F54722D3672580D2BD0F5041BAB404"}
2021-11-26T09:52:01.685Z puppeteer:protocol:RECV ◀ {"method":"Log.entryAdded","params":{"entry":{"source":"network","level":"error","text":"Failed to load resource: net::ERR_FAILED","timestamp":1.637920321684198e+12,"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","networkRequestId":"51.12"}},"sessionId":"00F54722D3672580D2BD0F5041BAB404"}

request interception + caching enabled -- page.goto timeout error

2021-11-26T11:45:11.872Z puppeteer:protocol:RECV ◀ {"method":"Network.requestWillBeSent","params":{"requestId":"52.12","loaderId":"5644EE3EE83599BBB48F2CC13EFA02F9","documentURL":"http://router/view/b9899918fcaf44fdaca9409b81e640bf?Context=US","request":{"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","method":"GET","headers":{"sec-ch-ua":"","Referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css","Origin":"http://router","sec-ch-ua-mobile":"?0","User-Agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":""},"mixedContentType":"none","initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin","isSameSite":false},"timestamp":30126.735991,"wallTime":1637927111.867024,"initiator":{"type":"parser","url":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},"type":"Font","frameId":"AFECEECEBE8E5378769F973A17C86B90","hasUserGesture":false},"sessionId":"7810447F1497636E5127E455614C38FA"}
2021-11-26T11:45:11.873Z puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-41.0","request":{"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","method":"GET","headers":{"sec-ch-ua":"","Origin":"http://router","sec-ch-ua-mobile":"?0","User-Agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":"","Accept":"*/*","Referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"AFECEECEBE8E5378769F973A17C86B90","resourceType":"Font","networkId":"52.12"},"sessionId":"7810447F1497636E5127E455614C38FA"}
2021-11-26T11:45:11.873Z puppeteer:protocol:SEND ► {"sessionId":"7810447F1497636E5127E455614C38FA","method":"Fetch.continueRequest","params":{"requestId":"interception-job-41.0","url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","headers":[{"name":"sec-ch-ua","value":""},{"name":"referer","value":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},{"name":"origin","value":"http://router"},{"name":"sec-ch-ua-mobile","value":"?0"},{"name":"user-agent","value":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36"},{"name":"sec-ch-ua-platform","value":""}]},"id":61}
2021-11-26T11:45:11.975Z puppeteer:protocol:RECV ◀ {"method":"Fetch.requestPaused","params":{"requestId":"interception-job-47.0","request":{"url":"https://int-us-east-1-scnext.flowbrite-statics.net/CircularXXWeb-Book.woff","method":"GET","headers":{"sec-ch-ua":"","Origin":"http://router","sec-ch-ua-mobile":"?0","User-Agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/93.0.4577.82 Safari/537.36","sec-ch-ua-platform":"","Accept":"*/*","Referer":"https://int-us-east-1-scnext.flowbrite-statics.net/one-ux.4c23247474d45168392e.css"},"initialPriority":"VeryHigh","referrerPolicy":"strict-origin-when-cross-origin"},"frameId":"AFECEECEBE8E5378769F973A17C86B90","resourceType":"Font","networkId":"52.12"},"sessionId":"7810447F1497636E5127E455614C38FA"}

@benallfree
Copy link
Contributor

I have a PR started to address this issue. Please test it if you can #7802.

@dekelev
Copy link

dekelev commented Dec 28, 2021

Issue still reproduces consistently on my end with puppeteer v13.0.1 while working fine when reverted back to v10.1.0
It's probably got something to do with the puppeteer-extra module and its plugins.

@dekelev
Copy link

dekelev commented Feb 3, 2022

I've noticed that page.setRequestInterception(true) is working fine in the latest puppeteer version when I'm removing the usage of enchant-puppeteer module, which is meant to provide a workaround when you need to manage old plugins (e.g. puppeteer-extra) in a cooperative request interception mode, otherwise this error is thrown: Error: Request is already handled!.

@benallfree
Copy link
Contributor

@dekelev I'm the author of enchant-pupeteer and recommend upgrading Puppeteer instead if possible. The enchantment never worked as well as the final stuff merged into the core.

@dekelev
Copy link

dekelev commented Feb 3, 2022

I agree, though it seems to require adding specific support for it in puppeteer-extra plugins, which I was trying to avoid. I guess I would have to fork these plugins since this issue doesn't seems to bother the author of those libs.

@benallfree
Copy link
Contributor

@dekelev I'd get in contact with puppeteer-extra and see where they're at with implementing cooperative mode.

berstend/puppeteer-extra#592
berstend/puppeteer-extra#364

@dekelev
Copy link

dekelev commented Feb 3, 2022

Awesome, thanks!

@rudolfbyker
Copy link

rudolfbyker commented May 11, 2022

I can still reproduce this on puppeteer version 14. Working on a minimal reproduction…

@rudolfbyker
Copy link

Here you go. It worked until puppeteer v9, and broke in v10: https://github.com/rudolfbyker/puppeteer-issue-7475-reproduction

@benallfree
Copy link
Contributor

benallfree commented May 12, 2022

@rudolfbyker it’s probable you’re experiencing an underlying CDP bug, not something in Puppeteer or higher level libraries. Please check out this and related tickets for more details. The minimal example you posted is actually quite a bit larger than the minimal examples needed to repro the CDP bug. I’m not able to dig into it further at this time, but I wanted to drop a note in case you had time to research the possibility that you’re experiencing a CDP bug.

@rudolfbyker
Copy link

it’s probable you’re experiencing an underlying CDP bug

What's CDP? Do you have a link so I can learn more?

not something in Puppeteer or higher level libraries.

Is there something else I should update / fix / make a repro for?

Please check out this and related tickets for more details.

Which tickets? Do you have a link?

I’m not able to dig into it further at this time, but I wanted to drop a note in case you had time to research the possibility that you’re experiencing a CDP bug.

Much appreciated.

@stale
Copy link

stale bot commented Jul 12, 2022

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.

@rudolfbyker
Copy link

Not stale, because I'm waiting for response from @benallfree :)

@mattvgm
Copy link

mattvgm commented Jul 30, 2022

I can confirm the problem persists.

@OrKoN OrKoN self-assigned this Jul 31, 2022
@OrKoN
Copy link
Collaborator

OrKoN commented Sep 6, 2022

So it seems only the repro from #7475 (comment) is reproducible with the current version of Puppeteer. It does look like another instance of double pause events sent by the backend. It does not lead to indefinite hanging for page.goto though.

alexivanov added a commit to alwaysmeticulous/meticulous-sdk that referenced this issue Dec 5, 2022
font request interception caching might trigger
a double requestPaused CDP event which triggers "request" Puppeteer
event to be emitted twice
which breaks tracking of in-flight requests. See
https://bugs.chromium.org/p/chromium/issues/detail?id=1196004 and
puppeteer/puppeteer#7475.
@czee
Copy link

czee commented Apr 5, 2023

I still see this issue with latest, v19.8.3

@OrKoN
Copy link
Collaborator

OrKoN commented May 16, 2023

I am not able to repro #7475 (comment) with v20.2.1

@OrKoN OrKoN closed this as completed May 16, 2023
@ShlomoVinny
Copy link

ShlomoVinny commented Jul 11, 2023

Just encountered this issue with:

Pptr: 20.8.0
Chrome: 114.0.5735.133

Using waitForRequest() works, the correct url is being intercepted and the intercepted request is paused and is interactable.
So, the request is being intercepted properly and postData is being overriden properly on await request.continue({postData: postData});
And the actual request is sent, but the browser hangs after sending the request, even though a redirect is to be expected, no redirect occurs. When checking the backend the data is there, its just chrome that hangs when continuing the request.

Edit:
Maybe using the Fetch Domain directly can be a workaround for this issue?

edit2:

It is! Interception and continuation do work properly using the Fetch Domain. With the version Im using, at least.

@deemstone
Copy link

fromEmitterEvent(this, PageEvent.Request)
.pipe(
mergeMap(originalRequest => {
return concat(
of(1),
merge(
fromEmitterEvent(this, PageEvent.RequestFailed),
fromEmitterEvent(this, PageEvent.RequestFinished),
fromEmitterEvent(this, PageEvent.Response).pipe(
map(response => {
return response.request();
})
)
).pipe(
filter(request => {
return request.id === originalRequest.id;
}),
take(1),
map(() => {
return -1;
})
)
);
}),
mergeScan((acc, addend) => {
return of(acc + addend);
}, 0),
takeUntil(fromEmitterEvent(this, PageEvent.Close)),
startWith(0)
)
.subscribe(this.#inflight$);

I had log out all these event ( on request start and finish ), and found that A different request.id="interception-job-8.0" appeared on oringalRequest , but no finish event for it , when setRequestInterception(true). That cause Page.#inflight$ counter could not down to 0 finally. The unnormal request.id=interception-job-8.0 , url is right equals to what url in goto(url) , and that request has got correct finish event before this.

Pptr: 22.6.1
Chrome: 120.0.6099.199 (arm64 on Mac)

@OrKoN
Copy link
Collaborator

OrKoN commented Mar 28, 2024

@deemstone do you have a minimal reproducible example or a CDP log? If the browser is not sending the fail or success events, we should report it to crbug.com

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests