setTimeout can cause process hangs when run in node:child_process

[AriPerkkio]

Describe the bug

When birpc is run inside node:child_process, it will leave unhandled NodeJS.Timeout handles hanging. These should be .unref()'ed.

birpc/src/index.ts

Lines 182 to 185 in 7b1fe90

	setTimeout(() => {
	reject(new Error(`[birpc] timeout on calling "${method}"`))
	rpcPromiseMap.delete(id)
	}, timeout)

But what's even more critical here is that these timeouts are not cleared with clearTimeout even when rpc call succees. This means that for every single rpc call, an Error object is created after 60 second timeout.

Reproduction script to be run in birpc repository - or if running as standalone, change the import path of birpc. You'll need to install why-is-node-running to see setTimeout pointed out.

$ pnpm i -D why-is-node-running

$ touch birpc-repro.mjs # Add code here
$ node birpc-repro.mjs

import { fork } from "node:child_process";
import { fileURLToPath } from "node:url";
import { createRequire } from "node:module";
import { createBirpc } from "./dist/index.mjs";

const require = createRequire(import.meta.url);
const whyIsNodeRunning = require("why-is-node-running");

const isMain = !Boolean(process.env.CHILD_PROCESS);
const filename = fileURLToPath(import.meta.url);

if (isMain) {
  console.log("[main-process]: Running", process.pid);

  const subprocess = fork(filename, { env: { CHILD_PROCESS: "true" } });
  subprocess.on("exit", () => console.log("[main-process] Subprocess exited"));

  console.log("[main-process]: Exiting", process.pid);
} else {
  console.log("[sub-process] Started", process.pid);

  let callback;
  const rpc = createBirpc(undefined, {
    post: (data) => callback({ t: "s", r: "Hello from RPC", i: data.i }),
    on: (cb) => (callback = cb),
  });

  // This will resolve quickly
  const response = await rpc.hello();
  console.log("[sub-process] Received", response);

  console.log("[sub-process] Exiting", process.pid);

  // If sub-process is stuck and wont gracefully exit, this will printout root causes
  setTimeout(() => whyIsNodeRunning(), 5_000).unref();

Output:

$ time node main.mjs 
[main-process]: Running 79086
[main-process]: Exiting 79086
[sub-process] Started 79087
[sub-process] Received Hello from RPC
[sub-process] Exiting 79087
There are 3 handle(s) keeping the process running

...

# Timeout
node:internal/async_hooks:202                
node:internal/async_hooks:504                
node:internal/timers:164                     
node:internal/timers:198                     
file:///x/y/z/birpc/dist/index.mjs:38
file:///x/y/z/birpc/dist/index.mjs:33
file:///x/y/z/birpc/main.mjs:36      
[main-process] Subprocess exited

real    1m0.113s            <-- This matches with birpc's timeout
user    0m0.142s
sys     0m0.029s

After unref()'ing the setTimeout:

$ time node main.mjs 
[main-process]: Running 81181
[main-process]: Exiting 81181
[sub-process] Started 81182
[sub-process] Received Hello from RPC
[sub-process] Exiting 81182
[main-process] Subprocess exited

real    0m0.104s
user    0m0.078s
sys     0m0.025s

Reproduction

Reproduction script above.

System Info

System:
    OS: macOS 13.4.1
    CPU: (8) arm64 Apple M2
    Memory: 836.11 MB / 16.00 GB
    Shell: 5.9 - /bin/zsh
  Binaries:
    Node: 18.17.0 - ~/.nvm/versions/node/v18.17.0/bin/node
    Yarn: 1.22.19 - /opt/homebrew/bin/yarn
    npm: 9.6.7 - ~/.nvm/versions/node/v18.17.0/bin/npm
    pnpm: 8.6.2 - ~/Library/pnpm/pnpm
  Browsers:
    Brave Browser: 114.1.52.122
    Chrome: 116.0.5845.96
    Safari: 16.5.2

Used Package Manager

pnpm

Validations

• Follow our Code of Conduct
• Read the Contributing Guide.
• Check that there isn't already an issue that reports the same bug to avoid creating a duplicate.
• Check that this is a concrete bug. For Q&A, please open a GitHub Discussion instead.
• The provided reproduction is a minimal reproducible of the bug.

[AriPerkkio]

But what's even more critical here is that these timeouts are not cleared with clearTimeout even when rpc call succees. This means that for every single RPC call, an Error object is created after 60 second timeout.

Using the minimal reproduction above and adding console.error inside setTimeout calls reveals that these errors are created for every RPC call.

setTimeout(() => {
+  console.error(`Creating error for ${method} even though it succeeded`);
  reject(new Error(`[birpc] timeout on calling "${method}"`))
  rpcPromiseMap.delete(id)
}, timeout)

$ time node main.mjs 
[main-process]: Running 81542
[main-process]: Exiting 81542
[sub-process] Started 81543
[sub-process] Received Hello from RPC
[sub-process] Exiting 81543
Creating error for hello even though it succeeded
[main-process] Subprocess exited