Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix process not ending correctly with shutdown hooks #14433

Closed
wants to merge 3 commits into from
Closed

Fix process not ending correctly with shutdown hooks #14433

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
56af69c
Fix process not ending correctly with shutdown hooks
thomaschaaf Jan 16, 2025
9c9151c
Update enable-shutdown-hooks-main.ts
thomaschaaf Jan 16, 2025
75291ec
Update enable-shutdown-hook.spec.ts
thomaschaaf Jan 16, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions integration/hooks/e2e/enable-shutdown-hook.spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ describe('enableShutdownHooks', () => {
.map((call: string) => call.trim());
expect(calls[0]).to.equal('beforeApplicationShutdown SIGHUP');
expect(calls[1]).to.equal('onApplicationShutdown SIGHUP');
expect(calls[2]).to.equal('node exit event called');
done();
}).timeout(10000);

Expand Down
4 changes: 4 additions & 0 deletions integration/hooks/src/enable-shutdown-hooks-main.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,10 @@ async function bootstrap() {

await app.listen(1800);
process.kill(process.pid, SIGNAL);

process.on('exit', () => {
console.log('node exit event called');
});
}

void bootstrap();
2 changes: 1 addition & 1 deletion packages/core/nest-application-context.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -368,7 +368,7 @@ export class NestApplicationContext<
await this.dispose();
await this.callShutdownHook(signal);
signals.forEach(sig => process.removeListener(sig, cleanup));
process.kill(process.pid, signal);
process.exit(0);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

image

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

Copy link
Member

@kamilmysliwiec kamilmysliwiec Jan 20, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

image

With nest start

image

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

image

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Author

@thomaschaaf thomaschaaf Jan 20, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.
});

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

} catch (err) {
Logger.error(
MESSAGES.ERROR_DURING_SHUTDOWN,
Expand Down