Nodemon waits forever for subprocesses to end #1633

jaybeeuu · 2019-11-20T22:59:48Z

nodemon -v: 2.0.0
node -v: 12.13.1
Operating system/terminal environment: Ubuntu 18.04.3 LTS/bash
Using Docker? What image:
Command you ran: nodemon --exec 'npm run-script start'

Expected behaviour

Restarting a process with the --exec command cleanly terminates the existing processes and restarts the supplied command.

Actual behaviour

When restarting a process, such as a node.js express server which has been started using the --exec option nodemon gets into an infinite loop, waiting for subprocesses to finish. Reporting

[nodemon] still waiting for 2 subprocess(es) to finish...

continually in the console, interleaved with the normal messaging for restarting the process.

Steps to reproduce

I have created a basic repro repo here:

https://github.com/jayseeare/nodemon-bug-repro

Running npm run debug and making a change in index.js will exhibit the problem.

Running npm run watch in the same repro does not exhibit the behaviour, and nor does running the same command with nodemon pinned to v1.19.1.

From the message and the versions I suspect this PR as having introduced the problem.

[nodemon] 2.0.0
[nodemon] to restart at any time, enter `rs`
[nodemon] watching dir(s): *.*
[nodemon] watching extensions: js,mjs,json
--------------
node: v12.13.1
nodemon: 2.0.0
command: /home/josh/.nvm/versions/node/v12.13.1/bin/node /home/josh/src/nodemon-bug-repro/node_modules/.bin/nodemon --exec npm run-script start --dump
cwd: /home/josh/src/nodemon-bug-repro
OS: linux x64
--------------
{
  run: false,
  system: { cwd: '/home/josh/src/nodemon-bug-repro' },
  required: false,
  dirs: [ '/home/josh/src/nodemon-bug-repro' ],
  timeout: 1000,
  options: {
    exec: 'npm run-script start',
    dump: true,
    ignore: [
      '**/.git/**',
      '**/.nyc_output/**',
      '**/.sass-cache/**',
      '**/bower_components/**',
      '**/coverage/**',
      '**/node_modules/**',
      re: /.*.*\/\.git\/.*.*|.*.*\/\.nyc_output\/.*.*|.*.*\/\.sass\-cache\/.*.*|.*.*\/bower_components\/.*.*|.*.*\/coverage\/.*.*|.*.*\/node_modules\/.*.*/
    ],
    watch: [ '*.*', re: /.*\..*/ ],
    ignoreRoot: [
      '**/.git/**',
      '**/.nyc_output/**',
      '**/.sass-cache/**',
      '**/bower_components/**',
      '**/coverage/**',
      '**/node_modules/**'
    ],
    restartable: 'rs',
    colours: true,
    execMap: { py: 'python', rb: 'ruby', ts: 'ts-node' },
    stdin: true,
    runOnChangeOnly: false,
    verbose: false,
    signal: 'SIGUSR2',
    stdout: true,
    watchOptions: {},
    execOptions: {
      script: null,
      exec: 'npm run-script start',
      args: [],
      scriptPosition: null,
      nodeArgs: undefined,
      execArgs: [],
      ext: 'js,mjs,json',
      env: {}
    },
    monitor: [
      '*.*',
      '!**/.git/**',
      '!**/.nyc_output/**',
      '!**/.sass-cache/**',
      '!**/bower_components/**',
      '!**/coverage/**',
      '!**/node_modules/**'
    ]
  },
  load: [Function],
  reset: [Function: reset],
  lastStarted: 0,
  loaded: [],
  watchInterval: null,
  signal: 'SIGUSR2',
  command: {
    raw: { executable: 'npm run-script start', args: [] },
    string: 'npm run-script start'
  }
}
--------------

The text was updated successfully, but these errors were encountered:

joseph-galindo · 2019-11-20T23:33:57Z

I'm able to confirm a similar issue in the following setup:

nodemon -v: 2.0.0
node -v: 12.6.0
OS: Mac OS 10.14.5
Docker? no

remy · 2019-11-21T09:14:11Z

Investigating now. Also wanted to say @jayseeare, thank you for providing a repo to replicate on - this makes things much easier ❤️

remy · 2019-11-21T09:15:57Z

Confirming this isn't an issue on Mac (my default setup).

Now testing Ubuntu so I can replicate.

remy · 2019-11-21T09:26:32Z

Confirmed. Am debugging now.

remy · 2019-11-21T09:41:57Z

Source of this problem is that the PR #1579 is trying to kill non-existent processes:

root@e2d215484450:/src# ps auxww
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.1  19912  3576 pts/0    Ss   09:25   0:00 bash
root       678  5.2  2.3 871764 47944 pts/0    Rl+  09:34   0:17 node ../../bin/nodemon.js --exec npm run-script start
root      1706  0.0  0.1  19904  3616 pts/1    Ss   09:36   0:00 bash
root      6802  0.0  0.0   4504   792 pts/0    S+   09:39   0:00 sh -c npm run-script start
root      6803  2.5  1.9 798168 40072 pts/0    Sl+  09:39   0:00 npm
root      6829  0.0  0.0   4508   800 pts/0    S+   09:39   0:00 sh -c node ./index.js
root      6830  1.9  1.8 567160 37680 pts/0    Sl+  09:39   0:00 node ./index.js
root      7564  0.0  0.0   4504   700 pts/0    S+   09:40   0:00 /bin/sh -c kill -0 2009 2032 2033
root      7565  0.0  0.1  36084  3236 pts/1    R+   09:40   0:00 ps auxww
root      7566  0.0  0.0   4372   796 pts/0    R+   09:40   0:00 /bin/sh -c kill -0 700 711 712

Note the kill signals (from multiple restarts) - they're trying to test for processes that aren't running at all.

remy · 2019-11-21T09:43:11Z

Looping @PePe79 in. @PePe79 I'm not sure why you're using kill -0 <pid> - I'm guessing this is a test signal, but it's providing a false positive as the process isn't running at all, and I'm trying to work out why this isn't being caught.

jaybeeuu · 2019-11-21T10:02:32Z

Thanks @remy. Sorry I didn't get round to debugging it last night; glad the repo helped though.

remy · 2019-11-21T10:23:00Z

I'm commenting on #1579 at the moment too, @PePe79 - I know why you're using kill -0 <pid> now.

remy · 2019-11-21T10:55:31Z

Quick update, I think I've got a fix ready to land.

remy · 2019-11-21T11:14:18Z

If you install nodemon@debug you should get the current build - I believe I've fixed the issue.

I've tested on:

Mac - with normal conditions
Mac - with waiting condition
Ubuntu - with normal conditions
Ubuntu - with waiting conditions

All working as I would expect now.

If someone can validate this with the debug release, I can publish.

julienvincent · 2019-11-21T11:15:39Z

Testing

julienvincent · 2019-11-21T11:17:16Z

Fixed for me on Mac Mojave, although I am getting this error in console:

[nodemon] restarting due to changes...
error Command failed with signal "SIGUSR2".
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

Doesn't seem to affect behaviour though

remy · 2019-11-21T11:19:15Z

Hmm, it shouldn't be doing that. @julienvincent can you run the same test with nodemon@1.x to see if you get the same error?

julienvincent · 2019-11-21T11:22:03Z

@remy Tested, can confirm I don't get that error with nodemon@1.x

remy · 2019-11-21T11:23:56Z

@julienvincent sod. Are you able to share how you're testing? I've got Mojave so I should be able to replicate. I'm using npm so I guess the first test is to use yarn.

remy · 2019-11-21T11:24:25Z

What's odd here is that SIGUSR2 isn't actually sent to the process, on the Mac it should be trimmed to USR2…

julienvincent · 2019-11-21T11:26:52Z

Internal repository so can't share the codebase, but I am running it through yarn:

package.json

{
  "scripts": {
    "start": "yarn build && env-cmd node ./dist/index.js",
    "watch": "nodemon --exec 'yarn start'"
  }
}

nodemon.json

{
  "ignore": ["dist", "types/dist", "types/schema"],
  "watch": ["src", "types/src"],
  "ext": "ts,json"
}

Possible that SIGUSR2 is coming from env-cmd?

remy · 2019-11-21T11:38:36Z

Oh possible. Are you able to reduce the example?

julienvincent · 2019-11-21T11:50:06Z

Ok after a bit of debugging I have narrowed it down to:

{
  "scripts": {
    "watch": "nodemon --exec './node_modules/.bin/tsc -b && node ./dist/index.js'"
  }
}

Which produces sh: line 1: 30956 User defined signal 2: 31 ./node_modules/.bin/tsc -b specifically when changing code while it is still compiling.

So it looks like tsc doesn't like the way it was killed. When using 1.x, tsc doesn't throw the above error.

Tested with typescript 3.6 and 3.7

remy · 2019-11-21T12:03:02Z

@julienvincent and you're on a mac, right? No in docker or anything?

julienvincent · 2019-11-21T12:03:51Z

Direct on mac, yea

remy · 2019-11-21T12:10:36Z

@julienvincent sorry, I don't do any typescript, so I'm hitting a few issues that I don't understand.

My simple ts file is this:

import http from 'http'

http.createServer(() => {}).listen(4000);

And tsc exits with code 2 - which itself is causing errors in nodemon (because 2 means "Misuse of shell builtins (according to Bash documentation)" and so nodemon bails - I appreciate this is typescript thing which you may not be able to answer).

MoonLiightz · 2019-11-21T12:15:14Z

You have to use one of the following:

import * as http from 'http';
http.createServer(() => {}).listen(4000);

or

import { createServer } from 'http';
createServer(() => {}).listen(4000);

remy · 2019-11-21T12:29:25Z

Huh. Still complains:

❯ tsc ./index.ts                                                                                                               
index.ts:1:30 - error TS2307: Cannot find module 'http'.

1 import { createServer } from 'http';
                               ~~~~~~
Found 1 error.

julienvincent · 2019-11-21T12:30:05Z

Let me setup a quick reproduce repo

remy · 2019-11-21T12:33:10Z

Ta - I'm about to shoot to an appointment but I'll be able to pick up in the evening - I really appreciate the repo and help.

julienvincent · 2019-11-21T12:45:53Z

https://github.com/julienvincent/nodemon-1633-reproduce

Kinda hacky, but you can reproduce this by running yarn watch and then editing the file before the tsc compilation has finished.

I also noticed that while using nodemon 2.0.0 the error reported above also gets logged when nodemon restarts.

MoonLiightz · 2019-11-21T12:57:19Z

Just in case you're interested @remy:
The error Cannot find module 'http' occurs because you are probably missing the @types/node module. In @julienvincent reproduce repo you can see it here.

remy · 2019-11-21T18:03:41Z

I've now tested with and without typescript, using @julienvincent's repo, and without typescript, there's no warning. It's only with typescript… :sigh:

remy · 2019-11-21T18:06:42Z

Actually - no it's not typescript, it's something to do with running more than one command in the exec arg…

remy · 2019-11-21T18:20:38Z

I can replicate with this:

nodemon -x 'echo running && sleep 20'

Then hit rs to restart and it will error.

I'm going to check this with nodemon@1 and if has the same error, I'm going to ship and separate this echo thing into a separate bug.

remy · 2019-11-21T18:24:05Z

dangit. nodemon@1 doesn't do it. Poop.

remy · 2019-11-21T18:41:25Z

Making progress. It's a system level problem, this replicates it (on a mac, and I suspect, on linux):

sh -c "sh -c sleep 20" & kill -USR2 $!
[1] 52500
[1]  + 52500 user-defined signal 2  sh -c "sh -c sleep 20"

Which is what nodemon is effectively doing.

kilianc · 2019-11-21T20:10:59Z

Confirmed it works on node:12.13.0-alpine nodemon@debug.

remy · 2019-11-21T22:42:25Z

@kilianc confirms the bug occurs or that the fix works?

remy · 2019-11-21T22:43:13Z

Can anyone on this thread reinstall nodemon@debug - should be 2.0.1-alpha.2 - I believe I've got the core issue fixed and the shell error also fixed, but it needs a few different ways of hitting to be sure.

kilianc · 2019-11-21T22:43:24Z

@remy that the fix works!

remy · 2019-11-21T22:44:12Z

@kilianc can you test with the latest @ debug version? I'm worried that I'm picking inside the core guts of nodemon and all the help I can test on test coverage will be appreciated!

julienvincent · 2019-11-21T22:47:43Z

@remy Seems the same issue still occurs for me with 2.0.1-alpha.2. sorry xD

remy · 2019-11-21T22:52:33Z

@julienvincent remind me what OS you're testing? Also can you try 2.0.1-alpha.3 - I've just published a simplified version.

julienvincent · 2019-11-21T22:54:08Z

@remy That latest one (alpha.3) works! I'm testing on macos Mojave

remy · 2019-11-21T22:55:35Z

okay, I'm going to push a PR, it'll kick off a load of tests, but hitting the sack now. I'll publish it in the morning if all the tests are good.

I'm pretty sure this last version is the one. Thank you all (so far).

julienvincent · 2019-11-21T22:58:46Z

Nice! Thanks for the good work 🙏 This thread was pretty entertaining. Until tomorrow!

Fixes #1633 Multiple parts but all localised to run.js: - Refactor the kill logic to be simpler - Consistently use pstree to determine sub process list - Pipe stderr through nodemon to squash `sh -c` error warning Bug was caused by waiting on multiple sub processes and if they all ended the logic would only subtract one from the count list (rather than the total number). I've refactored the code so that it doesn't use the `kill -0 <pid>` as this was a little confusing to read (it's effectively a no op) and switched to using pstree to test if any sub processes are still running. The logic for killing the processes has also been refactored to simplify. Before it would fork the logic based on whether `ps` existed on the system. Now it uses the same logic with the exception of the kill signal sent - when `ps` isn't on the system, we have to send numeric signals (I can't remember how I found that out, but I do remember it was a painful process!). The last part required due to a side effect of the refactor on kill: when a kill signial is sent to `sh -c` the shell prints a warning. Details on how to replicate: https://git.io/Je6d0 To squash this, I track if the process is about to be killed (by flagging the sub process right before the kill function call) and if there's an error whilst shutdown is in effect, the error is only printed to nodemon's detailed output (using nodemon -V).

joseph-galindo · 2019-11-21T23:18:33Z

Confirming that nodemon@2.0.1-alpha.3 seems to have fixed the issues I was running into on Mac OS 10.14.5. Thanks @remy for working on this.

Fixes #1633 Multiple parts but all localised to run.js: - Refactor the kill logic to be simpler - Consistently use pstree to determine sub process list - Pipe stderr through nodemon to squash `sh -c` error warning Bug was caused by waiting on multiple sub processes and if they all ended the logic would only subtract one from the count list (rather than the total number). I've refactored the code so that it doesn't use the `kill -0 <pid>` as this was a little confusing to read (it's effectively a no op) and switched to using pstree to test if any sub processes are still running. The logic for killing the processes has also been refactored to simplify. Before it would fork the logic based on whether `ps` existed on the system. Now it uses the same logic with the exception of the kill signal sent - when `ps` isn't on the system, we have to send numeric signals (I can't remember how I found that out, but I do remember it was a painful process!). The last part required due to a side effect of the refactor on kill: when a kill signial is sent to `sh -c` the shell prints a warning. Details on how to replicate: https://git.io/Je6d0 To squash this, I track if the process is about to be killed (by flagging the sub process right before the kill function call) and if there's an error whilst shutdown is in effect, the error is only printed to nodemon's detailed output (using nodemon -V).

abarre · 2019-11-26T16:00:00Z

Hi,

On my docker container, I started to see the message [nodemon] still waiting for 1 subprocess(es) to finish... after upgrading to 2.0.1.
Reverting to 2.0.0 seems to fix the issue.

nodemon -v: 2.0.1
node -v: 8.12.0
On docker image node:8.12.0-slim
Command you ran: nodemon --polling-interval 5000 --legacy-watch --signal SIGTERM devfe.js -- --config-file devfe2.conf --log-stdout

lorenc-tomasz · 2019-12-05T07:23:48Z

2.0.1 still have [nodemon] still waiting for 1 sub-process to finish...

I use cluster

remy · 2019-12-05T08:32:05Z

@lorenc-tomasz can you raise a new issue with a simplified case using cluster. I've not got a test case for that usage so it will be useful to replicate with.

ezze · 2019-12-05T11:29:04Z

@remy I raised new issue. Repo to reproduce is also there.

lorenc-tomasz · 2019-12-05T13:18:37Z

Thanks @ezze :)

remy added the bug confirmed bug label Nov 21, 2019

remy mentioned this issue Nov 21, 2019

fix: wait for all child processes to terminate (fixes issue #1476) #1579

Closed

remy mentioned this issue Nov 21, 2019

fix: ubuntu loop waiting for sub processes #1635

Merged

remy added the has PR label Nov 21, 2019

remy closed this as completed in #1635 Nov 22, 2019

snyk-bot mentioned this issue Dec 26, 2019

[Snyk] Upgrade nodemon from 2.0.1 to 2.0.2 w3bdesign/express#5

Closed

This was referenced Feb 2, 2020

[Snyk] Upgrade nodemon from 1.19.3 to 2.0.2 okikio/science-app#2

Merged

[Snyk] Upgrade nodemon from 1.19.3 to 2.0.2 okikio/leader-app#2

Closed

snyk-bot mentioned this issue Mar 25, 2020

[Snyk] Upgrade nodemon from 1.19.1 to 2.0.2 nodeshift-starters/opossum-examples#15

Merged

Nodemon waits forever for subprocesses to end #1633

Nodemon waits forever for subprocesses to end #1633

Comments

jaybeeuu commented Nov 20, 2019 • edited

Expected behaviour

Actual behaviour

Steps to reproduce

joseph-galindo commented Nov 20, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

jaybeeuu commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019 • edited

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

MoonLiightz commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

MoonLiightz commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019 • edited

kilianc commented Nov 21, 2019

remy commented Nov 21, 2019

remy commented Nov 21, 2019

kilianc commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019 • edited

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

remy commented Nov 21, 2019

julienvincent commented Nov 21, 2019

joseph-galindo commented Nov 21, 2019

abarre commented Nov 26, 2019

lorenc-tomasz commented Dec 5, 2019

remy commented Dec 5, 2019

ezze commented Dec 5, 2019 • edited

lorenc-tomasz commented Dec 5, 2019

jaybeeuu commented Nov 20, 2019 •

edited

julienvincent commented Nov 21, 2019 •

edited

remy commented Nov 21, 2019 •

edited

julienvincent commented Nov 21, 2019 •

edited

ezze commented Dec 5, 2019 •

edited