Network request fails after event loop is blocked for a few seconds (regression in v20)

Version

v20.16.0

Platform

Darwin MacBook.my.network 23.6.0 Darwin Kernel Version 23.6.0: Fri Jul  5 17:54:52 PDT 2024; root:xnu-10063.141.1~2/RELEASE_ARM64_T8103 arm64

Subsystem

http

What steps will reproduce the bug?

Block the event loop for 10 seconds via a long-running operation
Make a network request via http.request()

Code example:

const http = require("node:http");

const makePostRequest = () =>
  new Promise((resolve, reject) => {
    const onResponse = (res) => {
      let data = "";

      res.on("data", (chunk) => {
        data += chunk;
      });

      res.on("end", () => resolve(data));
    };

    const req = http.request(
      "http://127.0.0.1:3000/",
      { method: "POST" },
      onResponse,
    );

    req.on("error", (e) => reject(e));

    req.end();
  });

const makeRequests = async () => {
  await makePostRequest();

  console.log("First request worked");

  const timestamp = Date.now();

  // Block the event loop for 10 seconds
  while (Date.now() < timestamp + 10000);

  // Enable the following line and it will work:
  // await new Promise((resolve) => setTimeout(resolve, 10));

  await makePostRequest();

  console.log("It crashes before it gets here");
};

const server = http.createServer((req, res) => {
  console.log("Request received");
  res.statusCode = 200;
  res.setHeader("Content-Type", "text/plain");
  res.end("Hello world!\n");
});

server.listen(3000, "127.0.0.1", () => {
  console.log("Server up");

  makeRequests();
});

How often does it reproduce? Is there a required condition?

Reproduces always.

What is the expected behavior? Why is that the expected behavior?

The network request works.

What do you see instead?

The network request fails with ECONNRESET.
The network request does not reach the server.

Log from running the code above:

Server up
Request received
First request worked
node:internal/process/promises:391
    triggerUncaughtException(err, true /* fromPromise */);
    ^

Error: read ECONNRESET
    at TCP.onStreamRead (node:internal/stream_base_commons:218:20) {
  errno: -54,
  code: 'ECONNRESET',
  syscall: 'read'
}

Node.js v20.16.0

Process finished with exit code 1

Additional information

This is a regression. The code works on Node.js 18. It fails on Node.js 20.

If we wait for 10ms before running the network request, it works.

// repro.js
const http = require("node:http");

const makePostRequest = () =>
  new Promise((resolve, reject) => {
    const onResponse = (res) => {
      let data = "";

      res.on("data", (chunk) => {
        data += chunk;
      });

      res.on("end", () => resolve(data));
    };

    const req = http.request(
      "http://127.0.0.1:3000/",
      { method: "POST" },
      onResponse,
    );

    req.on("error", (e) => reject(e));

    req.end();
  });

const makeRequests = async () => {
  await makePostRequest();

  console.log("First request worked");

  const timestamp = Date.now();

  // Block the event loop for 10 seconds
  while (Date.now() < timestamp + 10000);

  // Enable the following line and it will work:
  // await new Promise((resolve) => setTimeout(resolve, 10));

  await makePostRequest();

  console.log("It crashes before it gets here");
};

const server = http.createServer((req, res) => {
  console.log("Request received");
  res.statusCode = 200;
  res.setHeader("Content-Type", "text/plain");
  res.end("Hello world!\n");
});

server.listen(3000, "127.0.0.1", () => {
  console.log("Server up");

  makeRequests();
});

$ node repro.js 
Server up
Request received
First request worked
node:internal/process/promises:391
    triggerUncaughtException(err, true /* fromPromise */);
    ^

Error: read ECONNRESET
    at TCP.onStreamRead (node:internal/stream_base_commons:218:20) {
  errno: -104,
  code: 'ECONNRESET',
  syscall: 'read'
}

Node.js v22.6.0

Reproducible in v20.0.0
Not reproducible in v18.20.4

This is caused by keepAlive, which is true by default after v18. I think this PR made that globally true for httpAgent and this issue surfaced.

If you reduce the while loop to less than 5 seconds, or add a header connection: 'close', the problem goes away.

Since the event loop was blocked and the socket destroy actions were scheduled in the next tick, your next request would be assigned to the socket to be destroyed.

IMHO, the best fix is probably about how to detect this at the request stage

@jazelly

Thank you so much for the information, @jazelly! I fixed the issue in my application by disabling keepAlive for now.

Agree that your suggested approach sounds good:

Before assigning a request to a socket, check if that socket is to be destroyed.
If yes, assign to a different (potentially new) socket instead.

Not suggesting Connection: close as a proper workaround, as it does not persist sockets.

Overall, I think this is an limitation in keepAlive or underlying socket implementation. As according to RFC 9112 standard, socket should not be closed immediately.

To avoid the TCP reset problem, servers typically close a connection in stages. First, the server performs a half-close by closing only the write side of the read/write connection. The server then continues to read from the connection until it receives a corresponding close by the client, or until the server is reasonably certain that its own TCP stack has received the client's acknowledgement of the packet(s) containing the server's last response. Finally, the server fully closes the connection.

@jazelly

Jason (@jazelly) and myself have spent some time to dig into this issue further more.

The reason why the second request failed is because the socket is no longer kept alive after 5 seconds and server tries to destroy the socket (this is asynchronous) however client side does not know the socket is being destroyed and still tries to send an request by reusing the same socket.

What happens next is that the request was assigned to the old socket by http agent at client side while the server is about to close the socket. The server then closed the socket and the request failed. connection: close in the header to force to open a new socket is one way to fix but not the optimal way as open up a socket is more costly, another workaround is always retrying the request.

You can find the similar issue here, hope it helps and please let us know if you have any other questions.

@jakecastelli

Thanks for digging further into it, @jakecastelli and @jazelly!

Let me summarize:

The server closes the connection upon Keep-Alive timeout.
The server can also close the connection at any other time.
In the repro from the issue, the client does not know about the connection closure because it hasn't processed incoming packets.
However, there's also a case where a similar issue happens without a blocked event loop:
Network packets sent by the server take some time to arrive on the client side.
So the client doesn't learn about connection closure immediately.
This leaves open a time window where the client doesn't know the connection is closed.
Requests made during that time window will also trigger ECONNRESET.
In that situation it's impossible to detect on the client side at request time that the connection was closed by the server.

Damn, that sucks. It means there's little we can do except for retrying.

Thanks for investigating and thanks for sharing! I appreciate the time you put into this. 🙌

I found this PR that will fix this issue. I verified it in my local env.

@jazelly

@jazelly That's awesome, thanks! Do you know the right process to bring attention back to the PR? It seems stale.

Collaborators with write permissions can help run CI for the PR. I don't have the permission but I believe once the CI is passed it will be landed soon.

@jazelly

Thanks, @jazelly, for getting the PR to the attention of the right people. :)

http: reduce likelihood of race conditions on keep-alive timeout

Navigation Menu

Repository navigation

Network request fails after event loop is blocked for a few seconds (regression in v20) #54293

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior? Why is that the expected behavior?

What do you see instead?

Additional information

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Network request fails after event loop is blocked for a few seconds (regression in v20) #54293

Description

Version

Platform

Subsystem

What steps will reproduce the bug?

How often does it reproduce? Is there a required condition?

What is the expected behavior? Why is that the expected behavior?

What do you see instead?

Additional information

Activity

avivkeller commented on Aug 9, 2024

trivikr commented on Aug 10, 2024

jazelly commented on Aug 10, 2024

nikwen commented on Aug 11, 2024

jazelly commented on Aug 22, 2024

jakecastelli commented on Aug 25, 2024

nikwen commented on Aug 26, 2024

jazelly commented on Aug 28, 2024

nikwen commented on Aug 28, 2024

jazelly commented on Aug 28, 2024

nikwen commented on Aug 28, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions