[#112] List what timed out #199

stereobooster · 2018-05-13T00:56:07Z

No description provided.

peterbe · 2018-05-15T14:11:05Z

Looking forward to find the time to dig into this. Looks exciting!
Sorry for being swamped.

peterbe

Unfortunately, it's not working. I put a couple of console.warn around the new code to make sure it matched on the error and to console.log out what the URLs were:

▶ ./bin/minimalcss.js -d --verbose -o /tmp/songsearch.css https://songsear.ch/song/Starchild/Wolfgun/537590 https://songsear.ch/ https://songsear.ch/q/searching
error.message=Navigation Timeout Exceeded: 30000ms exceeded
YES STARTS WITH
URLS: []
Error: Navigation Timeout Exceeded: 30000ms exceeded
    at Promise.then (/Users/peterbe/dev/JAVASCRIPT/minimalcss/node_modules/puppeteer/lib/NavigatorWatcher.js:71:21)
    at <anonymous>

Basically, it didn't manage to track any URLs.

peterbe · 2018-05-18T12:13:17Z

src/run.js

+            error.message += `\nFor one of the following urls: ${urls.join(
+              ', '
+            )}`;
+          } else if (urls.length > 0) {


This could just be } else if (urls.length) {

peterbe · 2018-05-18T12:16:37Z

src/run.js

+        if (error.message.startsWith('Navigation Timeout Exceeded')) {
+          const urls = tracker.urls();
+          if (urls.length > 1) {
+            error.message += `\nFor one of the following urls: ${urls.join(


That sentence is odd. It'd make sense if it started with ...for once of the.

I'm thinking we can be more direct and blunt. E.g.:

if (url.length) { error.message += `Tracked URLs that have NOT finished: ${urls.join(',')}` }

Also, I thin the word should be URLs (not urls) since it's an acronym of Uniform Resource Locator.

peterbe · 2018-05-18T12:21:52Z

src/tracker.js

@@ -0,0 +1,18 @@
+const createTracker = page => {


This could do with a doc string. I don't know what the right JSDoc notation should be but we ought to explain its purpose in life.

"A function that sets up request events on a Puppeteer.Page instance so that we can keep track of which URLs have started being request and which have finished. Ultimately its purpose is it be able to, at any point (e.g. an unexpected navigation error), be able to say which URLs have not finished. Having this list of URLs can be helpful when debugging why you get unpredictable timeouts."

peterbe · 2018-05-18T12:25:00Z

src/tracker.js

@@ -0,0 +1,18 @@
+const createTracker = page => {
+  const requests = new Set();


Why a set? How is a request hashed to be unique?
Also what happens if you have something like:

$(function() { window.setInterval(function() { fetch('/api/check-for-new-content').then(...) }, 1000) }

Or if there's a repeated <img src="same.png"> and the URL it resolves to doesn't have cache-control.

Nevermind this. A set is fine. It keeps it simple. We can revisit this later.

peterbe · 2018-05-18T12:26:31Z

tests/main.test.js

+  } catch (e) {
+    expect(e.message).toMatch('Navigation Timeout Exceeded: 2000ms exceeded');
+    expect(e.message).toMatch(
+      'For one of the following urls: http://localhost:3000/timeout.css?1, http://localhost:3000/timeout.css?2'


That comma is a bit weird. Perhaps we should do it like this:

error.message += `For one of the following urls:\n${urls.join('\n')}`

peterbe · 2018-05-18T12:40:41Z

I put a couple of more console.log inside tracker.js's onStarted and onFinished and then analyzed the output and concluded this:

https://songsear.ch/song/Starchild/Wolfgun/537590                                2 ['ADDING', 'DELETING']
https://songsear.ch/static/css/main.3196ddc2.css                                 2 ['ADDING', 'DELETING']
https://songsear.ch/static/ga.js                                                 2 ['ADDING', 'DELETING']
https://songsear.ch/static/js/main.824bb95d.js                                   2 ['ADDING', 'DELETING']
https://songsearch-2916.kxcdn.com/static/albums/2017/05/12/04/63881_300x300.jpg  2 ['ADDING', 'DELETING']
https://www.google-analytics.com/analytics.js                                    2 ['ADDING', 'DELETING']
https://www.google-analytics.com/r/collect                                       2 ['ADDING', 'DELETING']
https://songsear.ch/api/song/537590/amazon                                       2 ['ADDING', 'DELETING']
https://songsear.ch/api/song/537590/youtube                                      2 ['ADDING', 'DELETING']
https://songsear.ch/api/song/537590/affiliate/amazon                             2 ['ADDING', 'DELETING']
https://songsear.ch/api/song/537590/affiliate/itunes                             2 ['ADDING', 'DELETING']
https://images-na.ssl-images-amazon.com/images/I/21hPdSeQlAL._SL75_.jpg          2 ['ADDING', 'DELETING']
https://images-na.ssl-images-amazon.com/images/I/51un9j%2BsvaL._SL75_.jpg        2 ['ADDING', 'DELETING']
https://i.ytimg.com/vi/10JQ6XzqxuU/hqdefault.jpg                                 2 ['ADDING', 'DELETING']
https://songsear.ch/api/song/537590/related                                      2 ['ADDING', 'DELETING']

Note that that for every URL started, there's a deleted one.

peterbe · 2018-05-18T13:23:02Z

I butchered tracker.js by writing a thing that sets up an event for every single thing that's documented in the API. Then I analyzed it, after it failed.

https://songsear.ch/song/Starchild/Wolfgun/537590                                4 ['request', 'response', 'framenavigated', 'requestfinished']
https://songsear.ch/static/css/main.3196ddc2.css                                 3 ['request', 'response', 'requestfinished']
https://songsear.ch/static/ga.js                                                 3 ['request', 'response', 'requestfinished']
https://songsear.ch/static/js/main.824bb95d.js                                   3 ['request', 'response', 'requestfinished']
https://songsearch-2916.kxcdn.com/static/albums/2017/05/12/04/63881_300x300.jpg  2 ['request', 'requestfailed']
https://www.google-analytics.com/analytics.js                                    3 ['request', 'response', 'requestfinished']
https://www.google-analytics.com/r/collect                                       3 ['request', 'response', 'requestfinished']
https://songsear.ch/api/song/537590/amazon                                       3 ['request', 'response', 'requestfinished']
https://songsear.ch/api/song/537590/youtube                                      3 ['request', 'response', 'requestfinished']
https://songsear.ch/api/song/537590/affiliate/amazon                             3 ['request', 'response', 'requestfinished']
https://songsear.ch/api/song/537590/affiliate/itunes                             3 ['request', 'response', 'requestfinished']
https://images-na.ssl-images-amazon.com/images/I/21hPdSeQlAL._SL75_.jpg          2 ['request', 'requestfailed']
https://images-na.ssl-images-amazon.com/images/I/51un9j%2BsvaL._SL75_.jpg        2 ['request', 'requestfailed']
https://i.ytimg.com/vi/10JQ6XzqxuU/hqdefault.jpg                                 2 ['request', 'requestfailed']
https://songsear.ch/api/song/537590/related                                      3 ['request', 'response', 'requestfinished']

Nothing interesting again. What was expected to fail, failed. No richer in knowledge as to why it crashes.

peterbe · 2018-05-18T13:30:50Z

Basically, I think puppeteer is failing us here in that something times out that was never sent to the event system. Perhaps a service-worker or something like that. (e.g. the URLs I tested on uses service workers but beyond that there are no buggy banner ads, web workers, web sockets or anything fancy like that)

Last but not least, I did mess with the timeout and when I set it to 500ms it totally works. The URLs that didn't make it in 500ms are listed nicely in the error message. E.g.

Error: Navigation Timeout Exceeded: 500ms exceeded
For one of the following urls: https://songsear.ch/static/js/main.824bb95d.js, https://www.google-analytics.com/analytics.js
    at Promise.then (/Users/peterbe/dev/JAVASCRIPT/minimalcss/node_modules/puppeteer/lib/NavigatorWatcher.js:71:21)
    at <anonymous>

stereobooster · 2018-05-18T13:34:01Z

If we can not catch it with given script then we should reopen ticket in puppeteer repo

peterbe · 2018-05-18T13:47:37Z

If we can not catch it with given script then we should reopen ticket in puppeteer repo

Ha! That's what I was looking to do but got distracted. I'll try to do that.

By the way, I can run those URLs that I used to reproduce it locally. It's different in that I can't use HTTPS locally. But it's the same functionality inside the pages. Also, the other obvious difference is that when I use songsearch.local instead it resolves to 127.0.0.1.
When I do this, and hawkishly watch the local Nginx logs, it always works.
So, service workers are automatically disabled when you don't have HTTPS. That makes me, even more, believe it's the service workers that are failing.

stereobooster · 2018-05-18T13:49:44Z

You can use self-signed certificate for HTTPS and pass flag to puppeteer to allow untrusted certificates

peterbe · 2018-05-18T13:56:04Z

puppeteer/puppeteer#1908 (comment)

peterbe · 2018-05-18T13:56:49Z

I wonder if there's a flag to tell puppeteer to tell Chrome to not bother with service-workers (because, we're not ever coming back with a hot cache).

peterbe · 2018-05-29T14:23:54Z

Can you rebase this up so it uses the latest puppeteer. I really think the upgrade to puppeteer 1.4.0 solves the mysterious problem with strange timeout exceeded errors. At least I hope so.

stereobooster · 2018-06-19T18:40:12Z

I wonder if there's a flag to tell puppeteer to tell Chrome to not bother with service-workers (because, we're not ever coming back with a hot cache).

Yes. puppeteer/puppeteer#1396 (comment)

Can you rebase this up so it uses the latest puppeteer.

Done

timeout tracker nits

peterbe · 2018-06-20T17:58:20Z

Sorry. I must have forgot to run the tests after I changed the wording in the error message. Will fix that.

peterbe · 2018-06-20T18:02:56Z

There stereobooster#3

fix tests for 112-timeouts branch

stereobooster · 2018-06-20T18:05:08Z

I pushed this branch into this repo, you can open PR based on it, if you want to (and close this one)

peterbe · 2018-06-20T18:07:06Z

I approved, pending the Travis tests pass.

peterbe · 2018-06-20T18:07:53Z

There we go! Let's do it!

stereobooster force-pushed the 112-timeouts branch from 7fcbacd to 0ad8219 Compare May 13, 2018 01:06

peterbe reviewed May 18, 2018

View reviewed changes

peterbe mentioned this pull request May 18, 2018

Navigation Timeout Exceeded when using networkidle0 and no insight into what timed out puppeteer/puppeteer#1908

Closed

stereobooster added 2 commits June 19, 2018 20:36

[peterbe#112] List what timed out

ad3ad9d

timeout error for resources

8d58670

stereobooster force-pushed the 112-timeouts branch from b1ab902 to 8d58670 Compare June 19, 2018 18:36

peterbe and others added 2 commits June 20, 2018 13:48

timeout tracker nits

3928719

Merge pull request #2 from peterbe/timeout-tracker-nits

d245f61

timeout tracker nits

fix tests for 112-timeouts branch

07ffc88

Merge pull request #3 from peterbe/fix-tests-for-112-timeouts-branch

98305b6

fix tests for 112-timeouts branch

peterbe approved these changes Jun 20, 2018

View reviewed changes

stereobooster merged commit d5a78a2 into peterbe:master Jun 20, 2018

stereobooster deleted the 112-timeouts branch June 20, 2018 18:09

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[#112] List what timed out #199

[#112] List what timed out #199

stereobooster commented May 13, 2018

peterbe commented May 15, 2018

peterbe left a comment

peterbe May 18, 2018

peterbe May 18, 2018

peterbe May 22, 2018

peterbe May 18, 2018

peterbe May 18, 2018

peterbe Jun 20, 2018

peterbe May 18, 2018

peterbe commented May 18, 2018

peterbe commented May 18, 2018

peterbe commented May 18, 2018

stereobooster commented May 18, 2018

peterbe commented May 18, 2018

stereobooster commented May 18, 2018 •

edited

Loading

peterbe commented May 18, 2018

peterbe commented May 18, 2018

peterbe commented May 29, 2018

stereobooster commented Jun 19, 2018

peterbe commented Jun 20, 2018

peterbe commented Jun 20, 2018

stereobooster commented Jun 20, 2018

peterbe commented Jun 20, 2018

peterbe commented Jun 20, 2018

		@@ -0,0 +1,18 @@
		const createTracker = page => {
		const requests = new Set();

[#112] List what timed out #199

[#112] List what timed out #199

Conversation

stereobooster commented May 13, 2018

peterbe commented May 15, 2018

peterbe left a comment

Choose a reason for hiding this comment

peterbe May 18, 2018

Choose a reason for hiding this comment

peterbe May 18, 2018

Choose a reason for hiding this comment

peterbe May 22, 2018

Choose a reason for hiding this comment

peterbe May 18, 2018

Choose a reason for hiding this comment

peterbe May 18, 2018

Choose a reason for hiding this comment

peterbe Jun 20, 2018

Choose a reason for hiding this comment

peterbe May 18, 2018

Choose a reason for hiding this comment

peterbe commented May 18, 2018

peterbe commented May 18, 2018

peterbe commented May 18, 2018

stereobooster commented May 18, 2018

peterbe commented May 18, 2018

stereobooster commented May 18, 2018 • edited Loading

peterbe commented May 18, 2018

peterbe commented May 18, 2018

peterbe commented May 29, 2018

stereobooster commented Jun 19, 2018

peterbe commented Jun 20, 2018

peterbe commented Jun 20, 2018

stereobooster commented Jun 20, 2018

peterbe commented Jun 20, 2018

peterbe commented Jun 20, 2018

stereobooster commented May 18, 2018 •

edited

Loading