search

nodejs / undici

An HTTP/1.1 client, written from scratch for Node.js
https://nodejs.github.io/undici
MIT License
6.14k stars 531 forks source link

[HTTP/2] Aborted requests for same domain might fail unexpectedly #2364

Closed SukkaW closed 6 months ago

SukkaW commented 11 months ago

Bug Description

As the title, pipelined requests might fail unexpectedly if another request toward the same domain has been aborted:

node:assert:399
    throw err;
    ^

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

  assert(!this.aborted)

    at Request.onHeaders (/home/runner/undici-h2-promise-any/node_modules/undici/lib/core/request.js:235:5)
    at ClientHttp2Stream.<anonymous> (/home/runner/undici-h2-promise-any/node_modules/undici/lib/client.js:1804:17)
    at Object.onceWrapper (node:events:628:26)
    at ClientHttp2Stream.emit (node:events:513:28)
    at emit (node:internal/http2/core:330:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:85:22) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Node.js v18.16.1

Reproducible By

https://replit.com/@isukkaw/undici-h2-promise-any

const undici = require('undici');

undici.setGlobalDispatcher(new undici.Agent({
  allowH2: true,
  pipelining: 10
}));

const { fetch } = undici;

const fetchUbuntuXenialReleaseGpg = () => {
  const controller = new AbortController();
  return Promise.any(
    [
      'https://mirror-cdn.xtom.com/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.com/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.com.hk/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.de/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.nl/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.ee/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.jp/ubuntu/dists/xenial/Release.gpg',
      'https://mirrors.xtom.au/ubuntu/dists/xenial/Release.gpg'
    ].map(async url => {
      try {
        const resp = await fetch(url, { signal: controller.signal });
        const text = await resp.text();
        // The body should have been consumed, abort the requests
        controller.abort();
        return text;
      } catch(e) {
        if (e.name !== 'AbortError') {
          console.error('Request Fail:', url)
          throw e;
        }
      }
    })
  );
};

const fetchDebianBookwormReleaseGpg = () => {
  const controller = new AbortController();
  return Promise.any(
    [
      'https://mirror-cdn.xtom.com/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.com/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.com.hk/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.de/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.nl/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.ee/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.jp/debian/dists/bookworm/Release.gpg',
      'https://mirrors.xtom.au/debian/dists/bookworm/Release.gpg'
    ].map(async url => {
      try {
        const resp = await fetch(url, { signal: controller.signal });
        const text = await resp.text();
        // The body should have been consumed, abort the requests
        controller.abort();
        return text;
      } catch(e) {
        if (e.name !== 'AbortError') {
          console.error('Request Fail:', url)
          throw e;
        }
      }
    })
  );
};

(async () => {
  const [ubuntu, debian] = await Promise.all([
    fetchUbuntuXenialReleaseGpg(),
    fetchDebianBookwormReleaseGpg()
  ]);

  console.log({
    ubuntu: ubuntu.length,
    debian: debian.length
  })
})();

Expected Behavior

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value: assert(!this.aborted) should never happened.

Logs & Screenshots

(node:3251) [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)
node:assert:399
    throw err;
    ^

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

  assert(!this.aborted)

    at Request.onHeaders (/home/runner/undici-h2-promise-any/node_modules/undici/lib/core/request.js:235:5)
    at ClientHttp2Stream.<anonymous> (/home/runner/undici-h2-promise-any/node_modules/undici/lib/client.js:1804:17)
    at Object.onceWrapper (node:events:628:26)
    at ClientHttp2Stream.emit (node:events:513:28)
    at emit (node:internal/http2/core:330:3)
    at process.processTicksAndRejections (node:internal/process/task_queues:85:22) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Node.js v18.16.1

Environment

Node.js 18.16.0 on Ubuntu 22.04.1

KhafraDev commented 11 months ago

@metcoder95

metcoder95 commented 11 months ago

Started doing some research about, and bug is in fact quite complex; it seems that somewhere we are reusing a request instance that was already aborted to handle a second request. Haven't found the root cause yet. I'll made more research later on

jackschu commented 11 months ago

The repro SukkaW provided still reproduces even with Pipelining disabled, maybe this issue should be re-titled?

Trying to swap to undici in our software, I'm able to get this stack trace, we only issue one request to a dummy /debug/stream endpoint which pushes one sse per second and abort it after a few seconds.

but we receive exactly one more chunk afterwards, resulting in this assertion failure

[10/25/2023, 6:25:20 PM] [PLATFORM_FETCH] Sending GET: https://localhost:8020/debug/stream undefined (GET /debug/stream YR+xTDLhXJa6jIE13bX3WWaFzDQx) 
undici init path /debug/stream
undici SUCCESS connected {"host":"localhost:8020","hostname":"localhost","protocol":"https:","port":"8020","servername":null,"localAddress":null}
(node:3957036) [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)
[10/25/2023, 6:25:20 PM] [PLATFORM_FETCH] Started response (200) for request GET (https://localhost:8020/debug/stream) undefined (GET /debug/stream YR+xTDLhXJa6jIE13bX3WWaFzDQx) 
data from in  client /debug/stream <Buffer 7b 22 30 22 3a 22 31 36 39 38 32 37 32 37 32 31 34 39 34 22 7d 0a 0a>
data from in  client /debug/stream <Buffer 7b 22 31 22 3a 22 31 36 39 38 32 37 32 37 32 32 34 39 34 22 7d 0a 0a>
data from in  client /debug/stream <Buffer 7b 22 32 22 3a 22 31 36 39 38 32 37 32 37 32 33 34 39 35 22 7d 0a 0a>
aborting
undici request error This operation was aborted /debug/stream
[10/25/2023, 6:25:24 PM] [PLATFORM_FETCH] Finished response (closed stream via abort controller) for request (GET https://localhost:8020/debug/stream YR+xTDLhXJa6jIE13bX3WWaFzDQx)
data from in  client /debug/stream <Buffer 7b 22 33 22 3a 22 31 36 39 38 32 37 32 37 32 34 34 39 34 22 7d 0a 0a>
Trace: Aborted! /debug/stream <Buffer 7b 22 33 22 3a 22 31 36 39 38 32 37 32 37 32 34 34 39 34 22 7d 0a 0a>

node:internal/event_target:912
  process.nextTick(() => { throw err; });
                           ^

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

  assert2(!this.aborted)

    at Request2.onData (/nix/store/wvxs5i3mvh1lbvay44i13d24yy9rn95k-esbuild_node/depengine_worker.js:4815:9)
    at ClientHttp2Stream.<anonymous> (/nix/store/wvxs5i3mvh1lbvay44i13d24yy9rn95k-esbuild_node/depengine_worker.js:7177:21)
    at ClientHttp2Stream.emit (node:events:527:28)
    at addChunk (node:internal/streams/readable:324:12)
    at readableAddChunk (node:internal/streams/readable:297:9)
    at ClientHttp2Stream.Readable.push (node:internal/streams/readable:234:10)
    at Http2Stream.onStreamRead (node:internal/stream_base_commons:190:23)
Emitted 'error' event on Worker instance at:
    at Worker.[kOnErrorMessage] (node:internal/worker:289:10)
    at Worker.[kOnMessage] (node:internal/worker:300:37)
    at MessagePort.<anonymous> (node:internal/worker:201:57)
    at MessagePort.[nodejs.internal.kHybridDispatch] (node:internal/event_target:643:20)
    at MessagePort.exports.emitMessage (node:internal/per_context/messageport:23:28)

Node.js v17.9.0