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

[steveluscher]

Bug Description

Under load, when used with an Agent dispatcher having allowH2 set to true, fetch will sporadically throw an ERR_ASSERTION.

Reproducible By

Click ‘fork and run’ here: https://replit.com/@StevenLuscher/DarkredIroncladMethods

Expected Behavior

If the problem is that the underlying request is failing, I would expect it to trigger the catch block. Otherwise, we may be looking at a bug with the http/2 implementation itself.

Logs & Screenshots

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

  assert(!this.aborted)

    at Request.onHeaders (/home/runner/DarkredIroncladMethods/node_modules/undici/lib/core/request.js:245:5)
    at ClientHttp2Stream.<anonymous> (/home/runner/DarkredIroncladMethods/node_modules/undici/lib/client.js:1793:17)
    at Object.onceWrapper (node:events:629:26)
    at ClientHttp2Stream.emit (node:events:514:28)
    at emit (node:internal/http2/core:331:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:85:22) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Environment

• Node.js v20.10.0
• Linux baa638bf460f 6.5.0-1013-gcp #⁠13~22.04.1-Ubuntu SMP Wed Jan 24 23:39:40 UTC 2024 x86_64 GNU/Linux
• undici 6.2.2

[metcoder95]

Having an early assessment it seems this might have to be with the streams handling for H2; I'll try to dig into later Today or Tomorrow, have an idea where to look at

[ktaekwon000]

Hi @metcoder95, thanks a lot for your work on the repo. Have you found the cause of the issue? This issue is affecting my workloads as well.

I also wanted to chip in that the trigger of this bug reminds me of nodejs/node#47130 which affected Keep-Alive http/1.1 requests. (There is a workaround in that thread involving undici with Keep-Alive hints, but from my personal experience if the server kills the TCP connection without providing the Keep-Alive hints, undici is vulnerable to the same bug as node-fetch)

[metcoder95]

👋

No, sadly I've had the time, but the issue you shared with me resembles, especially because we reuse the socket for the HTTP/2 session, meaning that if the Node.js implementation suffers from that, most likely ours will do as well; here the trick will be to try to reproduce it by disabling keep-alive; if interested into giving it a try, happy to guide you through it, otherwise I'll try to see if I can spend some time on it next week.

But without any doubt, thanks for the contexts, that's pretty valuable

[st3ffgv4]

Same problem for me

import { fetch, Agent } from "undici";

const agent = new Agent({ allowH2: true, connect: { keepAlive: false } });

const exec = () => {
    setInterval(async () => {
        const now = Date.now();
        try {
            const response = await fetch("https://http2.pro/api/v1", {
                dispatcher: agent,
                keepalive: false
            });
            await response.text();

            console.log(response.status);
        } catch (e) {
            console.error(e);
        }
        console.log(Date.now() - now)
    }, 1);
}


exec();

is quite annoying as I cannot use fetch as I would like and the script terminates without going into catch.

With http 1.1 this does not happen

Node.js v20.11.1
Windows 11
undici 6.7.1

EDIT:

Tried also with undici 6.10.1 AND/OR Nodejs 21.7.1 problem still persist:
I dig a bit deeper and the error that is causing the abortion of the stream is

TypeError: Cannot read properties of null (reading 'push')
at Object.onData (C:\Users\stefa\OneDrive\Desktop\b-node-test\node_modules\undici\lib\web\fetch\index.js:2233:28)
at Request.onData (C:\Users\stefa\OneDrive\Desktop\b-node-test\node_modules\undici\lib\core\request.js:254:29)
at ClientHttp2Stream. (C:\Users\stefa\OneDrive\Desktop\b-node-test\node_modules\undici\lib\dispatcher\client-h2.js:422:17)
at ClientHttp2Stream.emit (node:events:518:28)
at addChunk (node:internal/streams/readable:559:12)
at readableAddChunkPushByteMode (node:internal/streams/readable:510:3)
at Readable.push (node:internal/streams/readable:390:5)
at Http2Stream.onStreamRead (node:internal/stream_base_commons:190:23)
node:assert:408
throw err;

It seems that onData in client-h2.js is called before onHeaders (or onHeaders is never called) and the body is not initialized as Readable instance in fetch/index.js

@metcoder95 Do you have any idea/advices ?

[metcoder95]

@st3ffgv4 I tried your reproduction but it seems that after #2985 this might be done, can we close it?

[st3ffgv4]

@metcoder95 only one question (not related to this "bug", but for the same script),
If i run more fetches than my network can fullfill i get this assertion error

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:86:5)
at ClientHttp2Session.emit (node:events:518:28)
at emitClose (node:internal/http2/core:1089:8)
at TLSSocket.<anonymous> (node:internal/http2/core:1116: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: '=='
}

and before this i get lot of frameerrors

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.exec [as _onTimeout] (file:///C:/Users/gava9/OneDrive/Documents/progetti/b-node-test/dist/index.js:69:19) {
[cause]: InformationalError: HTTP/2: "frameError" received - type 1, code 2
at ClientHttp2Stream. (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:443:17)
at Object.onceWrapper (node:events:633:26)
at ClientHttp2Stream.emit (node:events:518:28)
at Http2Session.onFrameError (node:internal/http2/core:614:11) {
code: 'UND_ERR_INFO'
}
}

and then

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.exec [as _onTimeout] (file:///C:/Users/gava9/OneDrive/Documents/progetti/b-node-test/dist/index.js:69:19) {
[cause]: TypeError: Cannot read properties of null (reading 'ref')
at writeH2 (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:371:11)
at Object.write (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:129: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)
}

Is this behaviour intentional or is it a bug?

[metcoder95]

frameErrors behaves as expected, as they are received when failing to send a frame for a stream; it can be due to several reasons, so not related to undici.

For the third error, I'm not sure how did you trigger that; tried with your script without luck

[st3ffgv4]

try this one:

import { fetch, Agent } from "undici";

const agent = new Agent({ allowH2: true, connect: { keepAlive: false } });

const exec = () => {
    setInterval(async () => {
        //const now = Date.now();
        try {
            const response = await fetch("https://www.amazon.in/dram/renderLazyLoaded", {
                dispatcher: agent,
                keepalive: false
            });
            await response.text();

            //console.log(response.status);
        } catch (e) {
            console.error(e);
        }
        //console.log(Date.now() - now)
    }, 1);
}


exec();

Consider that i have 15 mb/s download and 1 mb/s upload (I'm not sure at 100% is a network problem, I'm supposing)

1711540592412 onHTTP2GoAway 0
1711540592416 NO SESSION!
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/test3.js:9:30) {
[cause]: TypeError: Cannot read properties of null (reading 'ref')
at writeH2 (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:374:11)
at Object.write (C:\Users\gava9\OneDrive\Documents\progetti\undici\lib\dispatcher\client-h2.js:130: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)
}
1711540592423 close
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:87:5)
at ClientHttp2Session.emit (node:events:518:28)
at emitClose (node:internal/http2/core:1089:8)
at TLSSocket.<anonymous> (node:internal/http2/core:1116: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.11.1

First i reach session onHTTP2GoAway with code 0 at timestamp 1711540592412
then in writeH2 client[kHTTP2Session] is null at timestamp 1711540592416
then session close at timestamp 1711540592423
And the assertion is triggered

[metcoder95]

I'm pretty much sure you're suffering from congestion control due to limited bandwidth, I'm running it and still not being able to reproduce it.

It's kind of an edge case then, but worth it to see if we can develop further on a different issue

[st3ffgv4]

@metcoder95 so do you think i can open new issue?

i was looking at the client-h2.js and the documentiation of node http2 and i have a question:
The errors chain starts when the goaway listener of Http2Session is triggered,
The errorCode is 0, so if i check the correspond meaning (https://nodejs.org/api/http2.html#error-codes-for-rst_stream-and-goaway) 0 means No Error
If i undestrand correctly, why the onHTTP2GoAway method is resetting

 client[kSocket] = null
 client[kHTTP2Session] = null

if the http2 documentations for goaway event says that "Transmits a GOAWAY frame to the connected peer without shutting down the Http2Session." ?

[metcoder95]

Yeah, because it's kind of weird what triggers that condition, although I would consider it an edge case.

The GOAWAY frame is used to initiate a shutdown of the session under a graceful initiation or an unrecoverable condition.
Within undici, we understand that frame as graceful shutdown and we start gracefully cancelling the enqueued requests gradually in a best-effort manner.
It is applied at a session level, for instance, we also need to clean up the session and all its primitives.

See: https://webconcepts.info/concepts/http2-frame-type/0x7

[steveluscher]

FWIW my repro no longer blows up on 6.10.2: https://replit.com/@StevenLuscher/DarkredIroncladMethods

[metcoder95]

Let's continue the other topic with #3011