Example HTTP/2 push does not appear to work

[tsnieman]

Basic process:

1. git clone git@github.com:google/node-fastify-auto-push.git
2. cd node-fastify-auto-push/samples/static-page
3. npm start -- --h2 --ap -p 3000
4. Open Google Chrome (v65) and navigate to https://localhost:3000/, bypass security warning, see "Wikipedia" load.
5. Open DevTools > Network Tab, reload page and notice that "Initiator" isn't "Push" (as one would expect it to be):
   
6. Try using nghttp2-client as I have seen suggested for testing "Push" (wherein pushed assets are represented by an asterisk next to their asset row):

nghttp -ans https://localhost:3000
[WARNING] Certificate verification failed: Hostname mismatch
Some requests were not processed. total=23, processed=8
***** Statistics *****

Request timing:
  responseEnd: the  time  when  last  byte of  response  was  received
               relative to connectEnd
 requestStart: the time  just before  first byte  of request  was sent
               relative  to connectEnd.   If  '*' is  shown, this  was
               pushed by server.
      process: responseEnd - requestStart
         code: HTTP status code
         size: number  of  bytes  received as  response  body  without
               inflation.
          URI: request URI

see http://www.w3.org/TR/resource-timing/#processing-model

sorted by 'complete'

id  responseEnd requestStart  process code size request path
  4     +3.01ms *    +1.78ms   1.23ms  200  285 /load_1.css
 10     +3.02ms *    +1.81ms   1.21ms  200   2K /images/40px-Edit-clear.svg.png
  6     +3.17ms *    +1.79ms   1.39ms  200   3K /images/50px-Question_book-new.svg.png
  8     +3.40ms *    +1.79ms   1.61ms  200   8K /images/220px-Node.js_logo.svg.png
  2     +3.66ms *    +1.77ms   1.89ms  200  49K /load_3.css
 19     +6.59ms      +4.68ms   1.91ms  200   2K /wikipedia.ico
 21     +6.91ms      +4.68ms   2.24ms  200  17K /images/220px-Ryan_Dahl.jpg
 23     +9.00ms      +6.08ms   2.92ms  200   1K /images/28px-Free_and_open-source_software_logo_(2009).svg.png

⚠️ The nghttp command seems to immediately crash our example server after displaying the above output. The crash is noted logged like this:

npm start -- --h2 --ap -p 3000

> sample-fastify-auto-push@0.1.0 start /home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
> node index.js "--h2" "--ap" "-p" "3000"

(node:31382) ExperimentalWarning: The http2 module is an experimental API.
Listening on port 3000
events.js:165
      throw er; // Unhandled 'error' event
      ^

Error [ERR_HTTP2_INVALID_STREAM]: The stream has been destroyed
    at ServerHttp2Stream.doSendFileFD (internal/http2/core.js:1990:18)
    at FSReqWrap.oncomplete (fs.js:171:5)
Emitted 'error' event at:
    at emitErrorNT (internal/streams/destroy.js:64:8)
    at process._tickCallback (internal/process/next_tick.js:178:19)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! sample-fastify-auto-push@0.1.0 start: `node index.js "--h2" "--ap" "-p" "3000"`
npm ERR! Exit status 1

Other details:

• tried with Node v9.11.1 and v9.11.0 (installed via nvm)
• tried with the node --expose-http2 flag
• tried in my own barebones repo here: https://github.com/tsnieman/fastify-http2/tree/fda3ad392737cb24a2d0ca6b85451412b7b1432b (this bug also trackered here)

---

Please let me know if there's any additional information I should provide.
I deeply appreciate any time someone might spend thinking about this.
Thank you.

[jinwoo]

Thank you for the report.

Was the step 4 your first connection to the server? In that case, pushes wouldn't happen because the auto-push plugin hadn't seen any traffic to record the request patterns. If you connect using another browser (or after clearing your cookie because the browser would've cached the resources), you would see pushes happen.

I'll try nghttp and investigate the crash.

[jinwoo]

I tested the sample app and as you reported, the push doesn't happen. Investigating now. It could be due to the recent upgrade of fastify-plugin or fastify-static.

[jinwoo]

@mcollina It looks like the onRequest hook & onSend hook that you added before are not called at all from fastify:

• https://github.com/google/node-fastify-auto-push/blob/master/ts/src/index.ts#L64
• https://github.com/google/node-fastify-auto-push/blob/master/ts/src/index.ts#L82

Did something change in the recent version of fastify?

[jinwoo]

@mcollina Never mind. It was my local setup that was broken. Hooks are called fine. Sorry for the noise.

[tsnieman]

Thanks for looking into this @jinwoo.

Was the step 4 your first connection to the server? In that case, pushes wouldn't happen because the auto-push plugin hadn't seen any traffic to record the request patterns. If you connect using another browser (or after clearing your cookie because the browser would've cached the resources), you would see pushes happen.

Yes, but I in step 5 I reload to watch the network panel (and to trigger a reload, as I guessed auto-push plugin needed to record some request patterns). Seems like you figured this out by trying the example yourself, but figured I'd echo for clarity.

[jinwoo]

Some things I noticed while debugging:

• Push seems to happen even though Chrome devtools indicates otherwise. When using nghttp, it clearly shows that pushes happen and the response times for those resources are much shorter than when push doesn't happen.

• I often see the same error that @tsnieman reported when using nghttp:

  Error [ERR_HTTP2_INVALID_STREAM]: The stream has been destroyed
      at ServerHttp2Stream.doSendFileFD (internal/http2/core.js:1990:18)
      at FSReqWrap.oncomplete (fs.js:171:5)
  Emitted 'error' event at:
      at emitErrorNT (internal/streams/destroy.js:64:8)
      at process._tickCallback (internal/process/next_tick.js:178:19)
  npm ERR! code ELIFECYCLE
  npm ERR! errno 1
  npm ERR! sample-fastify-auto-push@0.1.0 start: `node index.js "--h2" "--ap" "-p" "3000"`
  npm ERR! Exit status 1
  

  I think this happens when there's pending requests that are still being processed and the stream is closed. I'm not sure how to handle that because the error is thrown from the core. @mcollina Do you have an idea how that can be prevented?

[jinwoo]

I could catch that error from pushStream.on('error', ...). But it's not clear how to recover from that error. I'll dig more tomorrow.

[mcollina]

@jinwoo I think it's a bug in Chrome/Chromium. See https://bugs.chromium.org/p/chromium/issues/detail?id=821492.
If it's a untrusted certificate, the pushStream is not accepted.
Maybe you can have a look too.

@tsnieman can you check with Firefox too?

[mcollina]

If you generate your certificates with https://www.npmjs.com/package/tls-keygen, it should work correctly.

@jinwoo we should update the blog post to use that tool.

[tsnieman]

Thanks for the response @mcollina.

• (with untrusted certs) No luck with Firefox, in that I'm not seeing "gray circles" next to the network requests to assets (even after several reloads). AFAIK the "gray circles" (versus green) is the way one identifies Pushed assets, but feel free to correct me if I'm wrong.

• Tried generating (and trusting) my certs via tls-keygen as such:

# tls-keygen requirement: certutil
sudo apt install libnss3-tools

# next part is borrowed from
# https://capocasa.net/add-a-self-signed-certificate-to-google-chrome-in-ubuntu-linux:
# Create database (if it doesn't already exist)
mkdir -p ~/.pki/nssdb 
certutil -d sql:$HOME/.pki/nssdb -N
# ^^^ attempt to prevent error like "could not authenticate to token NSS Certificate DB.:
#  An I/O error occurred during security authorization." from the "entrust" feature of tls-keygen

# generate keys
npx tls-keygen "fake-trusted-key.pem" "fake-trusted-cert.pem"
# i didn't find that this tool's "entrust" feature actually trusted my certs; always gives the db error.

# trust the cert:
certutil -A -t "C,," -d $HOME/.pki/nssdb -n 'Fake Trusted Certificate' -i fake-trusted-cert.pem

• After doing this ⬆️ I was able to load a "trusted" session in Chrome and Firefox, but found that neither Chrome nor Firefox received assets via Push (still "Parsed" in Chrome and "green circles" in Firefox).
• The crash from nghttp still happens as well.

[jinwoo]

Yeah, using tls-keygen works for me. Chrome's devtools shows that pushes happen. Thanks for figuring out the Chrome issue and the workaround, @mcollina !

@tsnieman, I'm not sure why tls-keygen doesn't work for you. I'm on Mac and just running

$ npx tls-keygen

generated key.pem and cert.pem, which are signed for localhost. I then updated my source code to use those files instead of server.key and server.crt.

There's still the crash from nghttp. I'm still investigating.

[jinwoo]

I also forgot to mention that I had to update the package.json file in the samples/static-page directory. It was using older versions of fastify and fastify-static and it may cause the sample app to not work correctly. I'll commit the changes soon.

[jinwoo]

Reopening while I'm addressing some more things.

[jinwoo]

Now new npm versions of h2-auto-push and fastify-auto-push have been published. This should be fixed now.

@tsnieman Please try again with the new version and let us know the result. Thanks!

[tsnieman]

@jinwoo I seem to be having issues getting this working on Ubuntu despite the provided fixes. Here's some steps:

# Ubuntu 17.10

# Remove any NSS DB entries (trusted certs) that might exist
% rm ~/.pki/nssdb/*

/home/tyler/tmp-code
% git clone git@github.com:google/node-fastify-auto-push.git

/home/tyler/tmp-code
% cd node-fastify-auto-push/samples/static-page

/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% npm i

# check the NSS cert db
/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% certutil -d sql:$HOME/.pki/nssdb -L

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

# ^^^ Empty (as expected)

# Load up the cert from the repo
/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% certutil -d sql:$HOME/.pki/nssdb -A -t "P,," -n localhost-h2ap -i certs/cert.pem

# alternatively, i've seen this suggested:
# certutil -A -t "C,," -d $HOME/.pki/nssdb -n localhost-h2ap -i certs/cert.pem
# so feel free to try either one, but neither has fixed the "not receiving push" issue for me.

# more details on certutil commands here https://chromium.googlesource.com/chromium/src/+/lkcr/docs/linux_cert_management.md

# Verify it's in NSS DB
/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% certutil -d sql:$HOME/.pki/nssdb -L                                             

Certificate Nickname                                         Trust Attributes
                                                             SSL,S/MIME,JAR/XPI

localhost-h2ap                                               P,,

# At this point I completely stop/close Chrome, then start it again.

/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% npm start -- --h2 --ap -p 3000

> sample-fastify-auto-push@0.1.1 start /home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
> node index.js "--h2" "--ap" "-p" "3000"

(node:23497) ExperimentalWarning: The http2 module is an experimental API.
Listening on port 3000

At this point, I'm loading via a "valid/secure" cert, but still not getting any pushed assets after several reloads:

Though I will note that nghttp no longer crashes the server (even if run several times):

/home/tyler/tmp-code/node-fastify-auto-push/samples/static-page
% nghttp -ans https://localhost:3000
[WARNING] Certificate verification failed: self signed certificate
***** Statistics *****

Request timing:
  responseEnd: the  time  when  last  byte of  response  was  received
               relative to connectEnd
 requestStart: the time  just before  first byte  of request  was sent
               relative  to connectEnd.   If  '*' is  shown, this  was
               pushed by server.
      process: responseEnd - requestStart
         code: HTTP status code
         size: number  of  bytes  received as  response  body  without
               inflation.
          URI: request URI

see http://www.w3.org/TR/resource-timing/#processing-model

sorted by 'complete'

id  responseEnd requestStart  process code size request path
  4     +2.82ms *    +1.87ms    952us  200  285 /load_1.css
 10     +2.83ms *    +1.91ms    922us  200   2K /images/40px-Edit-clear.svg.png
  6     +2.97ms *    +1.88ms   1.09ms  200   3K /images/50px-Question_book-new.svg.png
  8     +3.19ms *    +1.88ms   1.30ms  200   8K /images/220px-Node.js_logo.svg.png
  2     +3.47ms *    +1.85ms   1.62ms  200  49K /load_3.css
 17     +7.10ms      +4.59ms   2.52ms  200  20K /load_2.css
 19     +7.58ms      +4.59ms   3.00ms  200   2K /wikipedia.ico
 23     +7.58ms      +5.84ms   1.75ms  200   1K /images/28px-Free_and_open-source_software_logo_(2009).svg.png
 21     +8.06ms      +4.59ms   3.47ms  200  17K /images/220px-Ryan_Dahl.jpg
 15     +9.14ms      +4.59ms   4.55ms  200  77K /load.js
 13     +9.69ms        +39us   9.65ms  200 162K /
 25     +9.72ms      +8.55ms   1.17ms  200   1K /images/30px-Commons-logo.svg.png
 27     +9.73ms      +8.55ms   1.18ms  200   3K /images/100px-Node.js_logo.svg.png
 29    +10.83ms      +9.73ms   1.09ms  200   68 /checkLoggedIn
 31    +10.86ms      +9.73ms   1.12ms  200   2K /images/wikimedia-button.png
 33    +10.86ms      +9.74ms   1.12ms  200   1K /images/poweredby_mediawiki_88x31.png

I'm imagining that some of the issues I'm experiencing is because of Ubuntu/NSS versus Mac/Keychain:

Is there a maintainer of this project using Ubuntu/Linux that can try using the example project?

[jinwoo]

@tsnieman You have to clear the cookies and browser caches when you reload the page after the first load. Look at the HTTP response code, 304. It's because the browser already has those resources in its cache, it'll just reuse them.

Cookies should also be cleared because auto-push stores the information related to what might be cached in the browser.

[tsnieman]

@jinwoo Even after clearing cookies (or using something like a fresh incognito session), Chrome v66.0.3359.139 does not indicate "Push" -- only "Parser".

[jinwoo]

@tsnieman I'm not sure what you mean by "Parser". What is the HTTP response code? Is it still 304? It means that the resources are still cached in the browser. You should clear both caches and cookies before reloading. Or use a different browser than the one used for the first load.

[tsnieman]

"Parser" is referring to the initiator, per Chrome devtools network panel. A successful HTTP/2 Push should look like:
See how it says "Push" in the "Initiator" column? Do you see this when you run the example in this repo?

I don't see "Push" in the "Initiator" column -- even using a fresh browser with cleared cache/cookies, or a fresh incognito session. This means that Chrome is loading assets after having parsed which assets to load from the HTML rather than having the assets in the browser's cache from the "Push". Just for clarity: I do this is with clear cache/cookies/browser after reloading several times in different browser.

Yes, my screenshots show that assets are 304, but Chrome never indicates or indicated that any asset was ever pushed, so the 304 seems to be referring to a cache from a parsed asset.

@jinwoo Would you please confirm that you are seeing "Push" in the initiator column of Chrome's devtools network panel?

If there's anything else I can do to further debug why Chrome does not show "Push" in my initiator column -- even if it means I have to do a screen recording of this entire process -- please let me know.

[jinwoo]

I do see "Push" in the devtools.

If you see 304, the browser still has those resources in the browser cache. I'm not sure how you cleared them.

[tsnieman]

@jinwoo OK, I think I got this workin. Seems to have just be a PEBCAK 🤤 Not really sure where I went wrong before (did the same thing I've been doing: testing in diff browsers, clearing caches, using "incognito mode", etc), but finally managed to get "Push" to show up reliably in incognito. Thank you for your time, and pardon the hassle.

[jinwoo]

No problem. Glad that it works for you. And thanks again for reporting this issue so that we could fix!