Cannot read properties of null (reading 'ref') using fetch with HTTP/2 enabled and assertion error #3011

st3ffgv4 · 2024-03-28T11:57:45Z

Bug Description

While making continuous HTTP/2 requests after certain amount of time (minutes), happens that session goaway event is triggered, but meanwhile the close event is not fired and when a new request is pushed this error is thrown

Details

1711624898513 START
(node:1108) [UNDICI-H2] Warning: H2 support is experimental, expect them to change at any time.
(Use node --trace-warnings ... to show where the warning was created)
1711625507059 TypeError: fetch failed
at fetch (/home/runner/UNdici-http2-test/node_modules/undici/index.js:109:13)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at async Timeout._onTimeout (file:///home/runner/UNdici-http2-test/index.js:10:19) {
[cause]: TypeError: Cannot read properties of null (reading 'ref')
at writeH2 (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client-h2.js:371:11)
at Object.write (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client-h2.js:129:7)
at _resume (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client.js:604:50)
at resume (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client.js:529:3)
at Client. (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client.js:259:31)
at [dispatch] (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client.js:314:20)
at Client.Intercept (/home/runner/UNdici-http2-test/node_modules/undici/lib/interceptor/redirect-interceptor.js:11:16)
at Client.dispatch (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/dispatcher-base.js:179:40)
at [dispatch] (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/pool-base.js:143:28)
at Pool.dispatch (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/dispatcher-base.js:179:40)
}
node:assert:399
throw err;
^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

assert(client[kPending] === 0)
at ClientHttp2Session.<anonymous> (/home/runner/UNdici-http2-test/node_modules/undici/lib/dispatcher/client-h2.js:86:5)
at ClientHttp2Session.emit (node:events:514:28)
at emitClose (node:internal/http2/core:1089:8)
at TLSSocket.<anonymous> (node:internal/http2/core:1116:7)
at TLSSocket.emit (node:events:526:35)
at node:net:337:12
at TCP.done (node:_tls_wrap:657:7) {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}

Reproducible By

https://replit.com/@gava97/UNdici-http2-test
(also run the test for minutes to replit.com throws the error)

Expected Behavior

No errors thrown or at least no assertion

Logs & Screenshots

1711624878827 START
(node:20740) [UNDICI-H2] Warning: H2 support is experimental, expect them to change at any time.
(Use node --trace-warnings ... to show where the warning was created)
1711625119036 onHTTP2GoAway client.destroyed false
1711625119037 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625119040 onHTTP2GoAway client.destroyed false
1711625119040 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625119040 onHTTP2GoAway client.destroyed false
1711625119041 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625119041 close client[kQueue].length 0
1711625119041 close requests.length 0 client.destroyed false
1711625119042 close client[kQueue].length 0
1711625119042 close requests.length 0 client.destroyed false
1711625119042 close client[kQueue].length 0
1711625119042 close requests.length 0 client.destroyed false
1711625119068 onHTTP2GoAway client.destroyed false
1711625119068 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625119069 close client[kQueue].length 0
1711625119069 close requests.length 0 client.destroyed false
1711625119076 onHTTP2GoAway client.destroyed false
1711625119076 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625119077 close client[kQueue].length 0
1711625119077 close requests.length 0 client.destroyed false
1711625610034 onHTTP2GoAway client.destroyed false
1711625610035 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0
1711625610035 writeH2 client[kHTTP2Session] is null
1711625610036 TypeError: fetch failed
at fetch (C:\Users\gava9\OneDrive\Documents\progetti\undici\index.js:109:13)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at async Timeout._onTimeout (file:///C:/Users/gava9/OneDrive/Documents/progetti/b-node-test/test.js:10:19) {
[cause]: TypeError: Cannot read properties of null (reading 'ref')
at writeH2 (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:379:11)
at Object.write (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:133:7)
at _resume (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:604:50)
at resume (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:529:3)
at Client. (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:259:31)
at [dispatch] (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:314:20)
at Client.Intercept (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\interceptor\redirect-interceptor.js:11:16)
at Client.dispatch (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\dispatcher-base.js:179:40)
at [dispatch] (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\pool-base.js:143:28)
at Pool.dispatch (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\dispatcher-base.js:179:40)
}
1711625610080 close client[kQueue].length 1
1711625610081 close client.destroyed false
node:assert:408
throw err;
^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

assert(client[kPending] === 0)
at ClientHttp2Session.<anonymous> (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:89:5)
at ClientHttp2Session.emit (node:events:518:28)
at emitClose (node:internal/http2/core:1109:8)
at TLSSocket.<anonymous> (node:internal/http2/core:1136:7)
at TLSSocket.emit (node:events:530:35)
at node:net:337:12
at TCP.done (node:_tls_wrap:657:7) {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}

Node.js v20.12.0

Environment

Windows 11
Nodejs v20.12.0
undici 6.10.2

Additional context

I put some logs in the h2-client.js
a goaway is fired

1711625610034 onHTTP2GoAway client.destroyed false
1711625610035 onHTTP2GoAway client[kQueue].length 0 client[kRunningIdx] 0

but before the session fires close event a new request is pushed but the client[kHTTP2Session] property is null (set to null on goaway)

1711625610035 writeH2 client[kHTTP2Session] is null

then the script goes to catch block

1711625610036 TypeError: fetch failed
at fetch (C:\Users\gava9\OneDrive\Documents\progetti\undici\index.js:109:13)
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at async Timeout._onTimeout (file:///C:/Users/gava9/OneDrive/Documents/progetti/b-node-test/test.js:10:19) {
[cause]: TypeError: Cannot read properties of null (reading 'ref')
at writeH2 (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:379:11)
at Object.write (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:133:7)
at _resume (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:604:50)
at resume (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:529:3)
at Client. (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:259:31)
at [dispatch] (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client.js:314:20)
at Client.Intercept (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\interceptor\redirect-interceptor.js:11:16)
at Client.dispatch (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\dispatcher-base.js:179:40)
at [dispatch] (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\pool-base.js:143:28)
at Pool.dispatch (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\dispatcher-base.js:179:40)
}

then when close finally fires

1711625610080 close client[kQueue].length 1
1711625610081 close client.destroyed false
node:assert:408
throw err;
^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

assert(client[kPending] === 0)
at ClientHttp2Session.<anonymous> (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:89:5)
at ClientHttp2Session.emit (node:events:518:28)
at emitClose (node:internal/http2/core:1109:8)
at TLSSocket.<anonymous> (node:internal/http2/core:1136:7)
at TLSSocket.emit (node:events:530:35)
at node:net:337:12
at TCP.done (node:_tls_wrap:657:7) {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: false,
expected: true,
operator: '=='
}

assetion error is thrown because client[kPending] is not 0, there still left requests in the queue

The text was updated successfully, but these errors were encountered:

st3ffgv4 · 2024-03-28T11:58:39Z

this is the continuation of #2808 (comment) with @metcoder95 (if u want to try again)

metcoder95 · 2024-03-28T16:32:08Z

I'll try to simulate it based on your network conditions, this stills reproducible on your side, right?

st3ffgv4 · 2024-03-28T16:39:48Z

But i don't think is related to network. i was able to reproduce the same error also on https://replit.com/@gava97/UNdici-http2-test, you have to just wait that this happens, idk from 5 minutes to 1 hour.
But, of course, i can reproduce the error whenever you want

i was further checking (not tested yet)
#2878

before that PR, the assert(client[kPending] === 0) was inside if (client.destroyed)
if the assert check was wrapped inside that if statement also now, i don't think the assertion error would happen because, based on my tests, client is not destroyed at that point.

but i don't know if it's the correct behaviour or is better to fix the "Cannot read properties of null (reading 'ref')" before

EDIT

On my side i can confirm that wrapping assert(client[kPending] === 0) inside an if statement if (client.destroyed) like it was before @ronag PR #2878 makes the code work ("Cannot read properties of null (reading 'ref')" still persist obviously but at least the script doesn't break brutally, for this i don't know really what can be the fix)

Example:

session.on('close', function () {
    const { [kClient]: client } = this

    console.log(Date.now(), "close", "client[kQueue].length", client[kQueue].length);

    const err = this[kError] || new SocketError('closed', util.getSocketInfo(this))

    client[kSocket] = null

    //if (client[kPending] > 0) console.log(Date.now(), "close", "client.destroyed", client.destroyed);
    if (client.destroyed) assert(client[kPending] === 0)

    // Fail entire queue.
    const requests = client[kQueue].splice(client[kRunningIdx])
    console.log(Date.now(), "close", "requests.length", requests.length, "client.destroyed", client.destroyed);
    for (let i = 0; i < requests.length; i++) {
      const request = requests[i]
      errorRequest(client, request, err)
    }

    client[kPendingIdx] = client[kRunningIdx]

    assert(client[kRunning] === 0)

    client.emit('disconnect', client[kUrl], [client], err)

    client[kResume]()
  })

st3ffgv4 · 2024-04-03T10:32:51Z

@metcoder95 have you tried? any news?

metcoder95 · 2024-04-03T10:40:56Z

Yeah, I see what the issue is now; its in the way we handle the goaway frame. We just null the socket and session but we do not trigger the close of the session, so further request can be enqueued, until the server closes the socket and eventually fall into the issue you posted.

I'm working on a fix, will try to have something soon

st3ffgv4 · 2024-04-19T07:55:53Z

@metcoder95 tested, seems to work pretty good now, many thanks.
Should we close this issue?

metcoder95 · 2024-04-19T09:47:31Z

Closed by #3057

st3ffgv4 added the bug Something isn't working label Mar 28, 2024

metcoder95 mentioned this issue Apr 3, 2024

assert(!this.aborted) triggers sporadically when allowH2 is set to true #2808

Closed

metcoder95 closed this as completed Apr 19, 2024

iiAku mentioned this issue Oct 23, 2024

fix: emitting unknown error event #3763

Closed

7 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cannot read properties of null (reading 'ref') using fetch with HTTP/2 enabled and assertion error #3011

Cannot read properties of null (reading 'ref') using fetch with HTTP/2 enabled and assertion error #3011

st3ffgv4 commented Mar 28, 2024 •

edited

Loading

st3ffgv4 commented Mar 28, 2024

metcoder95 commented Mar 28, 2024

st3ffgv4 commented Mar 28, 2024 •

edited

Loading

st3ffgv4 commented Apr 3, 2024

metcoder95 commented Apr 3, 2024

st3ffgv4 commented Apr 19, 2024

metcoder95 commented Apr 19, 2024

Cannot read properties of null (reading 'ref') using fetch with HTTP/2 enabled and assertion error #3011

Cannot read properties of null (reading 'ref') using fetch with HTTP/2 enabled and assertion error #3011

Comments

st3ffgv4 commented Mar 28, 2024 • edited Loading

Bug Description

Reproducible By

Expected Behavior

Logs & Screenshots

Environment

Additional context

st3ffgv4 commented Mar 28, 2024

metcoder95 commented Mar 28, 2024

st3ffgv4 commented Mar 28, 2024 • edited Loading

EDIT

st3ffgv4 commented Apr 3, 2024

metcoder95 commented Apr 3, 2024

st3ffgv4 commented Apr 19, 2024

metcoder95 commented Apr 19, 2024

st3ffgv4 commented Mar 28, 2024 •

edited

Loading

st3ffgv4 commented Mar 28, 2024 •

edited

Loading