Would be nice to know *what* timed out

[peterbe]

See

▶ ./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: Navigation Timeout Exceeded: 30000ms exceeded
    at Promise.then (/Users/peterbe/dev/JAVASCRIPT/minimalcss/node_modules/puppeteer/lib/NavigatorWatcher.js:71:21)
    at <anonymous>

So most likely some asset or URL in that got stuck and took more than 30s. But I have no insight into which one it might be.

[peterbe]

Curiously, this fails every time:

▶ ./bin/minimalcss.js -d --verbose -o /tmp/songsearch.css https://songsear.ch/

It's strange because I can see that the server did respond with a 200 OK twice. As expected!
Nginx logs:

73.180.105.76 - - [26/Jan/2018:16:08:29 +0000] "GET / HTTP/1.1" 200 5063 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_2) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/65.0.3312.0 Safari/537.36" "-" "songsear.ch" sn="songsear.ch" rt=0.005 ua="127.0.0.1:3000" us="200" ut="0.005" ul="14041" cs=-
73.180.105.76 - - [26/Jan/2018:16:08:30 +0000] "GET / HTTP/1.1" 200 5075 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_2) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/65.0.3312.0 Safari/537.36" "-" "songsear.ch" sn="songsear.ch" rt=0.007 ua="127.0.0.1:3000" us="200" ut="0.007" ul="14059" cs=-

I grepped the access logs and could see my queries coming in and finishing just fine.

[peterbe]

I wrapped the page.goto call in a try/catch and that does catch something:

-      response = await page.goto(pageUrl, {
-        waitUntil: ['domcontentloaded', 'networkidle0']
-      })
+      try {
+        response = await page.goto(pageUrl, {
+          waitUntil: ['domcontentloaded', 'networkidle0']
+        })
+      } catch(ex) {
+        console.warn('IT FAILED', pageUrl);
+        console.error(ex.toString());
+        throw ex
+      }
+

But the error isn't particularly useful. It just says:

IT FAILED https://songsear.ch/
Error: Navigation Timeout Exceeded: 30000ms exceeded
    at Promise.then (/Users/peterbe/dev/JAVASCRIPT/minimalcss/node_modules/puppeteer/lib/NavigatorWatcher.js:71:21)
    at <anonymous>

I wish that exception was more than just a string.

[peterbe]

I added a page.on('requestfailed' but it was of no use. It just logs the requests that were aborted (e.g. things we decide to not bother downloading).

[stereobooster]

try hidden: false - you will see browser window

[peterbe]

I tried launch({timeout: 20000, headless: false, slowMo: 750}) and a chromium opened up but there were no good clues in it.
Interestingly, that timeout of 20s didn't seem to take effect. I still got the same:

IT FAILED https://songsear.ch/
Error: Navigation Timeout Exceeded: 30000ms exceeded

...error.

[peterbe]

Trying with full debug on:

env DEBUG="puppeteer:*"  node --trace-warnings bin/minimalcss.js -d --verbose --skip google-analytics.com -o /tmp/songsearch.css https://songsear.ch/ > output.log 2>&1

https://gist.github.com/5b296866545f9e85eeb2e5e184b75d62

[peterbe]

Here's a reproducible case:

'use strict'
const puppeteer = require('puppeteer')
;(async () => {
  const browser = await puppeteer.launch({})
  const page = await browser.newPage()
  await page.setRequestInterception(true)
  page.on('request', request => request.continue())
  try {
    await page.goto('https://songsear.ch/', {
      waitUntil: 'networkidle0',    // fails
      // waitUntil: 'networkidle2',    // works
      timeout: 2000
    })
  } catch (ex) {
    console.warn('IT FAILED')
    console.error(ex.toString())
    throw ex
  }
  await browser.close()
})()

If I replace networkidle2 with networkidle0 things work.

[peterbe]

Here's the output when it fails:
https://gist.github.com/peterbe/c7c21131fbe23031034fea114dfd6b97

[stereobooster]

'use strict';
const puppeteer = require('puppeteer');

class InflightRequests {
  constructor(page) {
    this._page = page;
    this._requests = new Set();
    this._onStarted = this._onStarted.bind(this);
    this._onFinished = this._onFinished.bind(this);
    this._page.on('request', this._onStarted);
    this._page.on('requestfinished', this._onFinished);
    this._page.on('requestfailed', this._onFinished);
  }

  _onStarted(request) {
    this._requests.add(request);
  }
  _onFinished(request) {
    this._requests.delete(request);
  }

  inflightRequests() {
    return Array.from(this._requests);
  }

  dispose() {
    this._page.removeListener('request', this._onStarted);
    this._page.removeListener('requestfinished', this._onFinished);
    this._page.removeListener('requestfailed', this._onFinished);
  }
}

(async () => {
  const browser = await puppeteer.launch({});
  const page = await browser.newPage();
  await page.setRequestInterception(true);
  page.on('request', request => request.continue());

  const tracker = new InflightRequests(page);
  await page
    .goto('https://songsear.ch/', {
      waitUntil: 'networkidle0', // fails
      // waitUntil: 'networkidle2',    // works
      timeout: 1000
    })
    .catch(e => {
      console.log('Navigation failed: ' + e.message);
      const inflight = tracker.inflightRequests();
      console.log(inflight.map(request => '  ' + request.url()).join('\n'));
    });
  tracker.dispose();

  await browser.close();
})();

Result:

Navigation failed: Navigation Timeout Exceeded: 1000ms exceeded
  https://songsearch-2916.kxcdn.com/static/css/main.743e98de.css
  https://songsearch-2916.kxcdn.com/static/ga.js

Off-topic: there is an issue with serving assets from different domain. Picture from webpagetest.org

[peterbe]

First of all, does that mean the 1000ms timeout happened on https://songsearch-2916.kxcdn.com/static/css/main.743e98de.css or on https://songsearch-2916.kxcdn.com/static/ga.js or on both?

Second, what do you mean about an issue with serving assets from different domain?
That site, by the way, is already using minimalcss as a build-step so it has all the minimal CSS inlined and a piece of JS loads the https://songsearch-2916.kxcdn.com/static/css/main.743e98de.css URL later. However, it might be preloading thanks to this tag:

<link rel="preload" href="https://songsearch-2916.kxcdn.com/static/css/main.743e98de.css" as="style" onload="this.rel='stylesheet'">

[stereobooster]

First of all, does that mean the 1000ms timeout happened on https://songsearch-2916.kxcdn.com/static/css/main.743e98de.css or on https://songsearch-2916.kxcdn.com/static/ga.js or on both?

On both. It is not that server didn't respond, it is just browser had not enough time to download it.

If you would serve assets from the same domain with http2 you would save this 1 second (which is spent to connect to another domain). Just saying

[peterbe]

Yeah. With regards to songsear.ch I might just do that. I only just last month switched over to http2 on the main Nginx server. Now the extra connection cost outweighs the latency of the CDN proximity.

Either way, I think minimalcss should include this tooling to help "debugging". The original issue is something took more than 30,000ms (and it's probably not the CDN) but it would be awesome to know the URLs so that you can execute minimalcss again but with some extra skip patterns.

[peterbe]

I wonder if this is related: #213
Certainly feels like it will be.

[stereobooster]

Related #248

[stereobooster]

It seems I found error in puppeteer which cause it puppeteer/puppeteer#1454. Related stereobooster/react-snap#240