Fix process not ending correctly with shutdown hooks

[thomaschaaf]

fixes #14432

https://codesandbox.io/p/sandbox/sad-noyce-6zrk6c

PR Checklist

Please check if your PR fulfills the following requirements:

• The commit message follows our guidelines: https://github.com/nestjs/nest/blob/master/CONTRIBUTING.md
• Tests for the changes have been added (for bug fixes / features)
• Docs have been added / updated (for bug fixes / features)

PR Type

What kind of change does this PR introduce?

• Bugfix
• Feature
• Code style update (formatting, local variables)
• Refactoring (no functional changes, no api changes)
• Build related changes
• CI related changes
• Other... Please describe:

What is the current behavior?

Issue Number: #14432

What is the new behavior?

https://nodejs.org/api/process.html#event-exit is now called when shutdown is complete

Does this PR introduce a breaking change?

• Yes
• No

[coveralls]

Pull Request Test Coverage Report for Build ae0182d5-3e47-4d23-8019-8cf995f68613

Details

• 0 of 0 changed or added relevant lines in 0 files are covered.
• 2954 unchanged lines in 125 files lost coverage.
• Overall coverage decreased (-37.3%) to 52.407%

---

Files with Coverage Reduction	New Missed Lines	%
packages/microservices/deserializers/identity.deserializer.ts	1	50.0%
packages/microservices/errors/invalid-grpc-service.exception.ts	1	66.67%
packages/microservices/errors/invalid-json-format.exception.ts	1	50.0%
packages/websockets/utils/compare-element.util.ts	1	50.0%
packages/core/injector/modules-container.ts	1	60.0%
packages/websockets/errors/ws-exception.ts	1	91.67%
packages/core/injector/settlement-signal.ts	1	75.0%
packages/microservices/serializers/identity.serializer.ts	1	50.0%
packages/core/discovery/discoverable-meta-host-collection.ts	1	34.62%
packages/microservices/errors/invalid-grpc-package-definition-missing-package-definition.exception.ts	1	66.67%

Totals
Change from base Build bce98666-cc2f-44fd-a720-bf6ccf7d71b9:	-37.3%
Covered Lines:	4148
Relevant Lines:	7915

---

💛 - Coveralls

[kamilmysliwiec]

Not sure if I'm following. process.exit (force exit) shouldn't be necessary. We're also overriding the signal (the reason to kill the process) here

[thomaschaaf]

console.log("Hello CodeSandbox");

process.on("SIGTERM", () => {
  console.log("SIGTERM received");
  process.kill(process.pid, "SIGTERM");
});

process.on("exit", () => {
  console.log("about to exit");
});

setTimeout(() => {
  console.log("killing");
  process.kill(process.pid, "SIGTERM");
}, 1000);

There "about to exit" is called. I don't understand why my unit test is failing without changing to process.exit(0).

I understand you'd want to wait for node to start the shutdown process - maybe the problem is coming from nestjs/cli / commander not waiting or not emitting the exit event on the child process.

[kamilmysliwiec]

This doesn't work even if you run node dist/main (no NestJS CLI involved)

[thomaschaaf]

thomaschaaf@MacBookPro sigterm % cat index.js
console.log("Hello CodeSandbox");

process.on("SIGTERM", () => {
  console.log("SIGTERM received");
  process.kill(process.pid, "SIGTERM");
});

process.on("exit", () => {
  console.log("about to exit");
});

setTimeout(() => {
  console.log("killing");
  process.kill(process.pid, "SIGTERM");
}, 1000);

thomaschaaf@MacBookPro sigterm % node index.js
Hello CodeSandbox
killing
SIGTERM received
about to exit
thomaschaaf@MacBookPro sigterm % node -v
v18.18.2

[kamilmysliwiec]

Code

console.log('Hello Node.js');

process.on('exit', () => {
  console.log('about to exit');
});

setTimeout(() => {
  console.log('killing');
  process.kill(process.pid, 'SIGTERM');
}, 1000);

Node v20

[kamilmysliwiec]

I still cannot reproduce your issue with the following code:

import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  app.enableShutdownHooks();
  await app.listen(3000);

  console.log(`Application is running on: ${await app.getUrl()}`);

  process.on('SIGTERM', async () => {
    await app.close();
    console.log('SIGTERM received');
    process.kill(process.pid, 'SIGTERM');
  });

  process.on('exit', () => {
    console.log('about to exit');
  });

  setTimeout(() => {
    console.log('killing');
    process.kill(process.pid, 'SIGTERM');
  }, 1000);
}
bootstrap();

With node dist/main:

Application is running on: http://[::1]:3000
killing
SIGTERM received
about to exit

With nest start

Same with nest start --watch (npm run start:dev)

[thomaschaaf]

I know you just released your own json logger - so it might not be your issue.

In the end I only care the exit listener because pino is using https://www.npmjs.com/package/on-exit-leak-free to flush the logs in the shutdown scenario to clear the buffers of the logger. Pino is using a worker thread to do the writing to stdout to be more performant. One alternative solution I came up with was calling logger.flush() before the kill.

iamolegga/nestjs-pino#1859

[thomaschaaf]

I will try out my example again and upload it to github - maybe it's something that got changed with v11

[thomaschaaf]

I think you accidentally found the issue 🤯

I created https://github.com/thomaschaaf/debug-nest-js-on-exit you can start it with either

SIGTERM=1 ./node_modules/.bin/nest start

or

SIGTERM=0 ./node_modules/.bin/nest start

This toggles: https://github.com/thomaschaaf/debug-nest-js-on-exit/blob/main/src/main.ts#L30-L33

I have also added an extra console log in pino: https://github.com/thomaschaaf/debug-nest-js-on-exit/blob/main/node_modules/pino/lib/transport.js#L62

The interesting bit is if you have no handler for sigterm the process.on('exit') is not called. I don't understand why.. With the change in the pr it is "fixed" but I understand it seems to be more of a workaround. I guess we will just add a handler

process.on('SIGTERM', () => {
  // fix 'exit' event not triggered without this.
});

[kamilmysliwiec]

I can replicate the exact same behavior using plain Node.js (without the Nest framework/CLI), so I'm not sure if there's anything we need to change on our end.

[thomaschaaf]

Setting a

process.on('SIGTERM', () => {
  // fix 'exit' event not triggered without this.
});

seems to fix the issue that process.on('exit') does not get triggered.