I always got a timeout error after request completion.

[galenzh]

I send a request in Chrome and got the response correctly. But I always got a timeout error after about 2 minutes in the server terminal. I only got error in node 18 and windows 10, if I use node 16 there is no error.

[10:52:22.928] ERROR (16820): Request timeout
    tags: [
      "connection",
      "client",
      "error"
    ]
    err: {
      "type": "Error",
      "message": "Request timeout",
      "stack":
          Error [ERR_HTTP_REQUEST_TIMEOUT]: Request timeout
              at new NodeError (node:internal/errors:399:5)
              at onRequestTimeout (node:_http_server:787:30)
              at Server.checkConnections (node:_http_server:600:7)
              at listOnTimeout (node:internal/timers:569:17)
              at process.processTimers (node:internal/timers:512:7)
      "code": "ERR_HTTP_REQUEST_TIMEOUT"
    }

Support plan

• is this issue currently blocking your project? (yes):
• is this issue affecting a production system? (yes):

Context

• node version: v18.15.0
• module version: 21.3.1
• environment (e.g. node, browser, native): Windows 10, Chrome
• used with (e.g. hapi application, another framework, standalone, ...): hapi-pino 12.0.0
• any other relevant information:

  "dependencies": {
  "@hapi/boom": "^10.0.1",
  "@hapi/hapi": "^21.3.1",
  "@hapi/inert": "^7.1.0",
  "@hapi/vision": "^7.0.1",
  "dotenv": "^16.0.3",
  "echarts": "^5.4.2",
  "hapi-pino": "^12.0.0",
  "hapi-swagger": "^16.0.1",
  "joi": "^17.9.1",
  "pino-pretty": "^10.0.0"
  },
  "devDependencies": {
  "@hapi/code": "^9.0.3",
  "@hapi/lab": "^25.1.2",
  "eslint": "^8.38.0",
  "nodemon": "^2.0.22"
  }

How can we help?

This is a demo.

"use strict";

const Hapi = require("@hapi/hapi");

const init = async () => {
  const server = Hapi.server({
    port: 8080,
    host: "0.0.0.0",
  });

  await server.register({
    plugin: require("hapi-pino"),
    options: {
      transport: {
        target: "pino-pretty",
      },
      logRequestComplete: true,
    },
  });

  server.route({
    method: "GET",
    path: "/",
    handler: (request, h) => {
      return "Hello Hapi!";
    },
  });

  await server.start();
  console.log("Server running on %s", server.info.uri);
};

process.on("unhandledRejection", (err) => {
  console.log(err);
  process.exit(1);
});

init();

[kanongil]

Interesting. Maybe hapi doesn't properly clean up? Though it could also be a subtle node.js bug.

[galenzh]

Interesting. Maybe hapi doesn't properly clean up? Though it could also be a subtle node.js bug.

My colleague got same error when run my demo. I found if I use firefox or curl command there is no error.

[kanongil]

Thanks. I can confirm the Chrome?? specific issue on my macOS machine using node 19.

I bit of investigation with Wireshark show that Chrome opens an extra connection to the server, without sending any requests on it. This for some reason eventually triggers a node.js request timeout as you see.

Hapi sends a 400 Bad Request response to Chrome, but the connection stays open. This does not seem like the correct way to handle this.

While this is clearly a node.js error (ERR_HTTP_REQUEST_TIMEOUT should not trigger when only the TCP connection is open), I expect it would be prudent for Hapi to better handle this case.

[kanongil]

Further investigation into the node.js internals shows that it is the parser that somehow thinks that an initial request on a socket starts when the connection is opened, and not when the first packet data is received. A later pipelined request on the same connection won't trigger this issue.

The request expiration logic, is triggered in an interval loop controlled by the connectionsCheckingInterval option (default 30000 ms).

The .expired() check calls into native http parser code.

[kanongil]

I found a likely culprit, originally introduced in https://github.com/nodejs/node/commit/df08d527c2083b852d8456b88b39114f30525236. While the patch also applies to node 16, the effect is only seen on v18+ since this is when the server.requestTimeout default was changed from 0 to 300000.

FYI this issue likely won't be exposed when hapi is running behind a reverse proxy like nginx, which is a more typical production scenario.

[galenzh]

I found a likely culprit, originally introduced in nodejs/node@df08d52. While the patch also applies to node 16, the effect is only seen on v18+ since this is when the server.requestTimeout default was changed from 0 to 300000.

FYI this issue likely won't be exposed when hapi is running behind a reverse proxy like nginx, which is a more typical production scenario.

@kanongil Thank your so much for your help. You are right, This issue won't exposed when running behind a reverse proxy. Is it possible to do something to avoid this error in dev environment without a reverse proxy ? I use swagger web client in Chrome.

[kanongil]

You should be able to get the old behaviour by setting server.listener.requestTimeout = 0 once it is listening.

For a more long term solution, I expect that hapi should detect this case and just silently send a 408 response, similar to what node does if there is no clientError event listener. Oddly enough, this behaviour is not documented.