Tests hang

[stefan-guggisberg]

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)

[stefan-guggisberg]

Clarification: The process doesn't hang indefinitely. The process exits after exactly 2 minutes.

[mgabeler-lee-6rs]

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 nodejs/node#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.

[mgabeler-lee-6rs]

Possibly also related: grantila/fetch-h2#104