Forwarding signals correctly to child process

[anthonyalayo]

Summary

While using both ts-node-dev and ts-node for development and production, I noticed that ts-node-dev was not properly waiting for my child process to finish before exiting. This support was already added to ts-node here: TypeStrong/ts-node#419

Here's an example run after the changes:

> ts-node-dev --debug --transpile-only src/index.ts

...
...
Listening on port 3000
^C[DEBUG] 13:59:28 Process got SIGINT, killing child
[DEBUG] 13:59:28 Sending SIGINT to child pid 21096
SIGINT received, stopping incoming requests
incoming requests stopped, waiting for existing connections to finish
closing mongodb connection
mongoDB connection closed
exiting successfully
[DEBUG] 13:59:30 Child closed with code 0
[DEBUG] 13:59:30 Exiting process with code 0

@wclr let me know what I need to do to get this into our next release. Thanks!

[anthonyalayo]

@wclr is there perhaps another contributor with permissions that I could get review from? Thanks!

[anthonyalayo]

@wclr bump -- would be great to get this in!

[anthonyalayo]

@wclr would it be possible to merge this too? Just saw your activity on the other PR.

[wclr]

@anthonyalayo did you run tests on it manually? There are currently problems with travis CI integration here. I've been in a haste to merge this one, tests are not passing on my machine.

[anthonyalayo]

@wclr yeah I unfortunately had issues running the travis tests on my machine so I tested it all manually. Were they able to be resolved? If not I can try getting it going on my local, let me know.

[wclr]

the travis tests

It is not the travis tests its just tests. That are supposed to run -)

Such things especially should not be developed without tests. After merging your PR tests are not passing.

I've added build step. Try to run tests (yarn test) before merging your PR and after.

[anthonyalayo]

Great thanks @wclr let me take a look

[anthonyalayo]

Yeah I see the test fail difference on the previous commit versus the merge, will have a fix tonight.

[anthonyalayo]

@wclr can you share your launch.json? Since the project uses chai and mocha instead of jest, I can't simply run jest runner and throw in breakpoints. yarn test runs, but it's not allowing me enough debug visibility, I need breakpoint support.

[wclr]

What launch.json? I don't use debuggers with breakpoints. You may just analyze the changes you made and then apply them in steps. There is also yarn test-dev that runs tests in watch mode, and to start tsc build in watch mode use yarn build -w (I use vscode configured background task for this).

[anthonyalayo]

@wclr for something of this caliber, proper debugging is necessary.

I have attempted attaching debuggers to the forked processes, but no luck. I have attempted to have the child processes print to stdout/stderr, but no luck. Inside the process event handlers, nothing prints. I have seen far and wide that this is behavior on NodeJS. I cannot for the life of me get any vector of debuggability of this working, so I will have to give up on this.

I have code that relies on a graceful shutdown in order to clean up connections, like so:

async function shutdown(signal: string, server: Server) {
  console.log(`${signal} received, stopping incoming requests`);

  server.close(() => {
    console.log('incoming requests stopped, waiting for existing connections to finish');

    setTimeout(() => {
      console.log('closing mongodb connection');
      mongoose.connection.close(() => {
        console.log('mongoDB connection closed');
        console.log('exiting successfully');
        process.exit(0);
      });
    }, WAIT_EXISTING_REQS_MILLIS);
  });

  setTimeout(() => {
    console.log('graceful shutdown timed out, forcefully shutting down');
    process.exit(1);
  }, SHUTDOWN_TIMEOUT_MILLIS);
}

And without the fix that is reflected inside ts-node in TypeStrong/ts-node#419, the graceful shutdown won't occur. The current code does not wait for the child process to exit, it kills the parent earlier:

  // Relay SIGTERM
  process.on('SIGTERM', function () {
    log.debug('Process got SIGTERM')
    killChild()
    process.exit(0)
  })

Unfortunately I'm at my wits end with the lack of debuggability, so I will just place a bounty in the issues section.

[wclr]

First, why not just add a failing test for the case? Then I could look a what is going on.

[anthonyalayo]

@wclr sorry, could you clarify? A majority of the tests were failing, so any of those would be useful for investigating?

For example, I was attempting to debug the issue using this test:
https://github.com/wclr/ts-node-dev/blob/master/test/tsnd.test.ts#L44-L53

Unfortunately as I noted earlier, it was very difficult to debug for me as I had no success at getting logs or breakpoints in the child processes. If there is anything I can do to make it more debug friendly, please let me know.

For the record, I still believe these changes are worth it. I just sanity tested my changes again running ts-node-dev in docker and having the container restarted via a typical deployment process.

Without my fix (current master) ts-node-dev exits without closing the mongodb connection:

Watching for changes...
[server] [INFO] 09:44:00 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.1.1, typescript ver. 4.3.5)
[server] connected to mongodb
[server] Listening on port 3000
[server] SIGTERM received, stopping incoming requests
[server] incoming requests stopped, waiting for existing connections to finish
[server] [INFO] 09:44:48 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.1.1, typescript ver. 4.3.5)
[server] connected to mongodb
[server] Listening on port 3000
[server] SIGTERM received, stopping incoming requests
[server] incoming requests stopped, waiting for existing connections to finish
[server] [INFO] 09:45:22 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.1.1, typescript ver. 4.3.5)
[server] connected to mongodb
[server] Listening on port 3000

However with my changes, it properly closes the connection:

Watching for changes...
[server] [INFO] 09:20:32 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.0.0, typescript ver. 3.9.5)
[server] connected to mongodb
[server] Listening on port 3000
[server] SIGTERM received, stopping incoming requests
[server] incoming requests stopped, waiting for existing connections to finish
[server] [INFO] 09:22:01 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.0.0, typescript ver. 3.9.5)
[server] closing mongodb connection
[server] mongoDB connection closed
[server] exiting successfully
[server] connected to mongodb
[server] Listening on port 3000
[server] SIGTERM received, stopping incoming requests
[server] incoming requests stopped, waiting for existing connections to finish
[server] [INFO] 09:22:32 ts-node-dev ver. 1.1.8 (using ts-node ver. 9.0.0, typescript ver. 3.9.5)
[server] closing mongodb connection
[server] mongoDB connection closed
[server] exiting successfully
[server] connected to mongodb
[server] Listening on port 3000

I ran the deployment process a few time for sanity. A new container is coming up, while the old container successfully closes the database connections.

[wclr]

A majority of the tests were failing,

I mean narrow down the issue and add failing test for your case here: https://github.com/wclr/ts-node-dev/blob/master/test/tsnd.test.ts#L42

[anthonyalayo]

@wclr unfortunately that is the issue, I was not able to narrow down it down. So I was using the simplest test there as an example.

[anthonyalayo]

@wclr I tried for about 5 hours, but no luck. I would need some help to sink more time into it. If you could help, that would be greatly appreciated.

You may also try to create the repo which will show the failure.

I can do this, it would be a docker container, a barebones NodeJS server, and skaffold to run kubernetes locally. However, I dont know what value it would provide. I have logs showing the difference in behaviour, and I have my fork of the project which shows the fixed behaviour.

you should try, or we really can not apply any fix for an unknown issue.

To be fair, the issue is not unknown. It also occured in ts-node here: TypeStrong/ts-node#419

[MrLoh]

Did this ever get anywhere, I'm running into some issues because SIGINT doesn't seem to be handled properly and always exits the process with errors.