Closed stefan-guggisberg closed 3 years ago
Clarification: The process doesn't hang indefinitely. The process exits after exactly 2 minutes.
I ran into a similar issue that I believe has the same root cause. In my case, speccy
(https://github.com/wework/speccy) hangs when it is trying to download external references from servers that support HTTP/2.
I was able to bisect this to having been introduced in nodejs 12.17.0.
I ran with lots of node trace/debug stuff enabled, and comparing the succeeding and failing logs, I suspect that this was introduced by https://github.com/nodejs/node/pull/32958, but that's hard for me to verify.
Some snippets of debug traces (NODE_OPTIONS=--trace-tls NODE_DEBUG=*
) from where they start differing (note: this is a speccy lint
run, but the code that's running at this point is from this package). This starts just after the certificate exchange.
Working with 12.16.3:
TLS 301274: client onhandshakedone
TLS 301274: client _finishInit handle? true alpn h2 servername <snip>
TLS 301274: client emit secureConnect. authorized: true
HTTP2 301274: Http2Session client: setting up session handle
HTTP2 301274: Http2Session client: sending settings
HTTP2 301274: Http2Session client: submitting settings
HTTP2 301274: Http2Session client: created
HTTP2 301274: Http2Session client: initiating request
HTTP2 301274: Http2Session client: connected, initializing request
STREAM 301274: resume
(node:301274) Warning: Setting the NODE_DEBUG environment variable to 'http2' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
HTTP2 301274: Http2Stream 1 [Http2Session client]: _final shutting down
STREAM 301274: resume false
STREAM 301274: read 0
STREAM 301274: need readable false
STREAM 301274: length less than watermark true
STREAM 301274: do read
STREAM 301274: flow true
STREAM 301274: read undefined
STREAM 301274: need readable true
STREAM 301274: length less than watermark true
STREAM 301274: reading or ended false
Sent Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 162
Inner Content Type = ApplicationData (23)
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 545
Inner Content Type = Handshake (22)
NewSessionTicket, Length=260
ticket_lifetime_hint=172800
ticket_age_add=858443592
ticket_nonce (len=1): 00
ticket (len=242): <snip>
extensions, length = 4
extension_type=UNKNOWN(27242), length=0
NewSessionTicket, Length=260
ticket_lifetime_hint=172800
ticket_age_add=2125917300
ticket_nonce (len=1): 01
ticket (len=242): <snip>
extensions, length = 4
extension_type=UNKNOWN(27242), length=0
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 57
Inner Content Type = ApplicationData (23)
Sent Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 26
Inner Content Type = ApplicationData (23)
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 26
Inner Content Type = ApplicationData (23)
HTTP2 301274: Http2Session client: settings received
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 172
Inner Content Type = ApplicationData (23)
HTTP2 301274: Http2Stream 1 [Http2Session client]: headers received
HTTP2 301274: Http2Stream 1 [Http2Session client]: emitting stream 'response' event
The response finishes from here.
Failing with 12.17.0:
TLS 301302: client onhandshakedone
TLS 301302: client _finishInit handle? true alpn h2 servername <snip>
TLS 301302: client emit secureConnect. authorized: true
HTTP2 301302: Http2Session client: created
HTTP2 301302: Http2Session client: initiating request
STREAM 301302: resume
(node:301302) Warning: Setting the NODE_DEBUG environment variable to 'http2' can expose sensitive data (such as passwords, tokens and authentication headers) in the resulting log.
STREAM 301302: resume false
STREAM 301302: read 0
STREAM 301302: need readable false
STREAM 301302: length less than watermark true
STREAM 301302: do read
STREAM 301302: flow true
STREAM 301302: read undefined
STREAM 301302: need readable true
STREAM 301302: length less than watermark true
STREAM 301302: reading or ended false
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 545
Inner Content Type = Handshake (22)
NewSessionTicket, Length=260
ticket_lifetime_hint=172800
ticket_age_add=169979864
ticket_nonce (len=1): 00
ticket (len=242): <snip>
extensions, length = 4
extension_type=UNKNOWN(43690), length=0
NewSessionTicket, Length=260
ticket_lifetime_hint=172800
ticket_age_add=1669237012
ticket_nonce (len=1): 01
ticket (len=242): <snip>
extensions, length = 4
extension_type=UNKNOWN(43690), length=0
Received Record
Header:
Version = TLS 1.2 (0x303)
Content Type = ApplicationData (23)
Length = 57
Inner Content Type = ApplicationData (23)
STREAM 301302: readableAddChunk <Buffer <snip>>
STREAM 301302: emitReadable true false
STREAM 301302: emitReadable null
STREAM 301302: emitReadable_ false 40 false
STREAM 301302: flow null
STREAM 301302: maybeReadMore read 0
STREAM 301302: read 0
STREAM 301302: need readable true
STREAM 301302: length less than watermark true
STREAM 301302: do read
NET 301302: _read
The app hangs from here.
Possibly also related: https://github.com/grantila/fetch-h2/issues/104
When running the test suite (
npm test
) the tests complete successfully but the process doesn't terminate. I guess that's because some sockets are still open...(I am on macos)