search

szmarczak / http2-wrapper

Use HTTP/2 the same way like HTTP/1
MIT License
239 stars 18 forks source link

Repeat requests fail to reuse the first session #96

Closed Ingramz closed 1 year ago

Ingramz commented 1 year ago

Reproduction:

import got from 'got'
import http2 from 'http2-wrapper'

const http2agent = new http2.Agent()

const gotEx = got.extend({
    http2: true,
    agent: {http2: http2agent}
})

await gotEx.get('https://example.com/')
await gotEx.get('https://example.com/')
await gotEx.get('https://example.com/')
await gotEx.get('https://example.com/')

http2agent.destroy()

When running node with NODE_DEBUG="tls,http2", it can be seen that two http2 sessions are created, each with their own TLS handshakes. This is likely due to agent.normalizeOptions return value being different on initial request. Occurrence of each normalizeOptions is logged to illustrate that the value is different on first and second session. (First request belongs to session 1 and requests 2-4 belong to session 2)

TLS 32708: client _init handle? true
TLS 32708: client _init handle? true
TLS 32708: client initRead handle? true buffered? 0
TLS 32708: client initRead handle? true buffered? false
TLS 32708: client _start handle? true connecting? false requestOCSP? false
TLS 32708: client onhandshakedone
TLS 32708: client _finishInit handle? true alpn h2 servername example.com
TLS 32708: client emit secureConnect. authorized: true
[NORMALIZED] :(...args) => {
                                if (reuseSocket.destroyed) {
                                        return this.agent.createConnection(...args);
                                }

                                return reuseSocket;
                        }::::::::::::::::::::::::::::::::::::
HTTP2 32708: Http2Session client: setting up session handle
HTTP2 32708: Http2Session client: sending settings
HTTP2 32708: Http2Session client: submitting settings
HTTP2 32708: Http2Session client: created
[NORMALIZED] :(...args) => {
                                if (reuseSocket.destroyed) {
                                        return this.agent.createConnection(...args);
                                }

                                return reuseSocket;
                        }::::::::::::::::::::::::::::::::::::
(node:32708) Warning: Setting the NODE_DEBUG environment variable to 'http2' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
(Use `node --trace-warnings ...` to show where the warning was created)
TLS 32708: client emit session
TLS 32708: client emit session
HTTP2 32708: Http2Session client: new settings received
HTTP2 32708: Http2Session client: initiating request
HTTP2 32708: Http2Session client: connected, initializing request
HTTP2 32708: Http2Stream 1 [Http2Session client]: shutting down writable on _final
HTTP2 32708: Http2Session client: settings received
HTTP2 32708: Http2Stream 1 [Http2Session client]: headers received
HTTP2 32708: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
HTTP2 32708: Http2Stream 1 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
TLS 32708: client _init handle? true
HTTP2 32708: Http2Session client: created
TLS 32708: client initRead handle? true buffered? false
TLS 32708: client _start handle? true connecting? false requestOCSP? false
TLS 32708: client onhandshakedone
TLS 32708: client _finishInit handle? true alpn h2 servername example.com
TLS 32708: client emit secureConnect. authorized: true
HTTP2 32708: Http2Session client: setting up session handle
HTTP2 32708: Http2Session client: sending settings
HTTP2 32708: Http2Session client: submitting settings
TLS 32708: client emit session
TLS 32708: client emit session
HTTP2 32708: Http2Session client: new settings received
HTTP2 32708: Http2Session client: initiating request
HTTP2 32708: Http2Session client: connected, initializing request
HTTP2 32708: Http2Stream 1 [Http2Session client]: shutting down writable on _final
HTTP2 32708: Http2Session client: settings received
HTTP2 32708: Http2Stream 1 [Http2Session client]: headers received
HTTP2 32708: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
HTTP2 32708: Http2Stream 1 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 32708: Http2Session client: initiating request
HTTP2 32708: Http2Session client: connected, initializing request
HTTP2 32708: Http2Stream 3 [Http2Session client]: shutting down writable on _final
HTTP2 32708: Http2Stream 3 [Http2Session client]: headers received
HTTP2 32708: Http2Stream 3 [Http2Session client]: emitting stream 'response' event
HTTP2 32708: Http2Stream 3 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 32708: Http2Session client: initiating request
HTTP2 32708: Http2Session client: connected, initializing request
HTTP2 32708: Http2Stream 5 [Http2Session client]: shutting down writable on _final
HTTP2 32708: Http2Stream 5 [Http2Session client]: headers received
HTTP2 32708: Http2Stream 5 [Http2Session client]: emitting stream 'response' event
HTTP2 32708: Http2Stream 5 [Http2Session client]: destroying stream
HTTP2 32708: Http2Session client: destroying
HTTP2 32708: Http2Session client: start closing/destroying undefined
HTTP2 32708: Http2Session client: destroying
HTTP2 32708: Http2Session client: start closing/destroying undefined
HTTP2 32708: Http2Session client: finishSessionClose
HTTP2 32708: Http2Session client: finishSessionClose
HTTP2 32708: Http2Session client: finishSessionClose socket end undefined undefined
HTTP2 32708: Http2Session client: finishSessionClose socket end undefined undefined

After patching the offending option to return an empty string in that function, everything will be performed in one session as one would expect (see below). Unfortunately I'm not too familiar with the internals of this project to really comment on what a proper fix in a case such as this would look like.

TLS 17400: client _init handle? true
TLS 17400: client _init handle? true
TLS 17400: client initRead handle? true buffered? 0
TLS 17400: client initRead handle? true buffered? false
TLS 17400: client _start handle? true connecting? false requestOCSP? false
TLS 17400: client onhandshakedone
TLS 17400: client _finishInit handle? true alpn h2 servername example.com
TLS 17400: client emit secureConnect. authorized: true
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 17400: Http2Session client: setting up session handle
HTTP2 17400: Http2Session client: sending settings
HTTP2 17400: Http2Session client: submitting settings
HTTP2 17400: Http2Session client: created
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
(node:17400) Warning: Setting the NODE_DEBUG environment variable to 'http2' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
(Use `node --trace-warnings ...` to show where the warning was created)
TLS 17400: client emit session
TLS 17400: client emit session
HTTP2 17400: Http2Session client: new settings received
HTTP2 17400: Http2Session client: initiating request
HTTP2 17400: Http2Session client: connected, initializing request
HTTP2 17400: Http2Stream 1 [Http2Session client]: shutting down writable on _final
HTTP2 17400: Http2Session client: settings received
HTTP2 17400: Http2Stream 1 [Http2Session client]: headers received
HTTP2 17400: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
HTTP2 17400: Http2Stream 1 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 17400: Http2Session client: initiating request
HTTP2 17400: Http2Session client: connected, initializing request
HTTP2 17400: Http2Stream 3 [Http2Session client]: shutting down writable on _final
HTTP2 17400: Http2Stream 3 [Http2Session client]: headers received
HTTP2 17400: Http2Stream 3 [Http2Session client]: emitting stream 'response' event
HTTP2 17400: Http2Stream 3 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 17400: Http2Session client: initiating request
HTTP2 17400: Http2Session client: connected, initializing request
HTTP2 17400: Http2Stream 5 [Http2Session client]: shutting down writable on _final
HTTP2 17400: Http2Stream 5 [Http2Session client]: headers received
HTTP2 17400: Http2Stream 5 [Http2Session client]: emitting stream 'response' event
HTTP2 17400: Http2Stream 5 [Http2Session client]: destroying stream
[NORMALIZED] :::::::::::::::::::::::::::::::::::::
HTTP2 17400: Http2Session client: initiating request
HTTP2 17400: Http2Session client: connected, initializing request
HTTP2 17400: Http2Stream 7 [Http2Session client]: shutting down writable on _final
HTTP2 17400: Http2Stream 7 [Http2Session client]: headers received
HTTP2 17400: Http2Stream 7 [Http2Session client]: emitting stream 'response' event
HTTP2 17400: Http2Stream 7 [Http2Session client]: destroying stream
HTTP2 17400: Http2Session client: destroying
HTTP2 17400: Http2Session client: start closing/destroying undefined
HTTP2 17400: Http2Session client: finishSessionClose
HTTP2 17400: Http2Session client: finishSessionClose socket end undefined undefined
szmarczak commented 1 year ago

Sorry for huge delay. Fixed in f1a1776d4b1aef1cd47d55b1a950986e86145a09 and will make a release later today.