ECONNRESET on restarts

[roy7]

• nodemon -v:
• node -v:
• Operating system/terminal environment:
• Command you ran:

jroy:/code/leela-zero-server$ node node_modules/nodemon/bin/nodemon.js -v
1.14.3
jroy:/code/leela-zero-server$ node -v
v8.9.3
jroy@sjeng:/code/leela-zero-server$ uname -a
Linux 4.4.0-101-generic #124-Ubuntu SMP Fri Nov 10 18:29:59 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

node node_modules/nodemon/bin/nodemon.js --watch test.js test.js >> log.test 2>&1

Expected behaviour

Restart app cleanly.

Actual behaviour

[nodemon] restarting due to changes...
events.js:183
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at _errnoException (util.js:1024:11)
    at Pipe.onread (net.js:615:25)

Steps to reproduce

I'm not sure how to further debug this to help provide some info back. It's also possible it's my own app and not nodemon. I used version 1.12.1 for a while and it would never restart any more when I changed my .js file. Now with the upgrade to 1.14.3 it does auto restart again, but I rarely get this crash when I "touch test.js". Previously I would reattach my screen session and enter 'rs' to the console. In either situation, only maybe 1 out of 20 restarts would cause a crash.

In attempts to catch this error if it's happening inside my own app, I added this:

process.on('uncaughtException', (err) => {
    console.error('Caught exception: ' + err);
});

But it isn't catching this restart related ECONNRESET error. I'm unsure if I'm catching it wrong to try and debug my own app, or if the error is being thrown my nodemon itself?

---

If applicable, please append the --dump flag on your command and include the output here ensuring to remove any sensitive/personal details or tokens.

--------------
node: v8.9.3
nodemon: 1.14.3
command: /usr/bin/node /home/jroy/code/leela-zero-server/node_modules/nodemon/bin/nodemon.js --dump --watch test.js test.js
cwd: /home/jroy/code/leela-zero-server
OS: linux x64
--------------
{ run: false,
  system: { cwd: '/home/jroy/code/leela-zero-server' },
  required: false,
  dirs: [ '/home/jroy/code/leela-zero-server/test.js' ],
  timeout: 1000,
  options:
   { dump: true,
     watch: [ 'test.js', re: /test\.js/ ],
     ignore:
      [ '**/.git',
        '**/.nyc_output',
        '**/.sass-cache',
        '**/bower_components',
        '**/coverage',
        '**/node_modules',
        re: /.*.*\/\.git|.*.*\/\.nyc_output|.*.*\/\.sass\-cache|.*.*\/bower_components|.*.*\/coverage|.*.*\/node_modules/ ],
     ignoreRoot:
      [ '**/.git',
        '**/.nyc_output',
        '**/.sass-cache',
        '**/bower_components',
        '**/coverage',
        '**/node_modules' ],
     restartable: 'rs',
     colours: true,
     execMap: { py: 'python', rb: 'ruby' },
     stdin: true,
     runOnChangeOnly: false,
     verbose: false,
        '**/coverage',
        '**/node_modules',
        re: /.*.*\/\.git|.*.*\/\.nyc_output|.*.*\/\.sass\-cache|.*.*\/bower_components|.*.*\/coverage|.*.*\/node_modules/ ],
     ignoreRoot:
      [ '**/.git',
        '**/.nyc_output',
        '**/.sass-cache',
        '**/bower_components',
        '**/coverage',
        '**/node_modules' ],
     restartable: 'rs',
     colours: true,
     execMap: { py: 'python', rb: 'ruby' },
     stdin: true,
     runOnChangeOnly: false,
     verbose: false,
     signal: 'SIGUSR2',
     stdout: true,
     watchOptions: {},
     execOptions:
      { script: 'test.js',
        exec: 'node',
        args: [],
        scriptPosition: 0,
        nodeArgs: undefined,
        execArgs: [],
        ext: 'js,json',
        env: {} },
     monitor:
      [ 'test.js',
        '!**/.git',
        '!**/.nyc_output',
        '!**/.sass-cache',
        '!**/bower_components',
        '!**/coverage',
        '!**/node_modules' ] },
  load: [Function],
  reset: [Function: reset],
  lastStarted: 0,
  loaded: [ '/home/jroy/code/leela-zero-server/package.json' ],
  watchInterval: null,
  signal: 'SIGUSR2',
  command:
   { raw: { executable: 'node', args: [ 'test.js' ] },
     string: 'node test.js' } }
--------------

[remy]

Can you provide the test.js file too? Or a pared down version at least?

[roy7]

Could I send it to you privately somehow and not copy/paste the whole thing into here? Thanks.

[remy]

Sure, or strip it right down so that you've just got a replicable example. Otherwise you can email me at remy@leftlogic.com

…

On Wed, 27 Dec 2017, 14:54 Jonathan Roy, ***@***.***> wrote: Could I send it to you privately somehow and not copy/paste the whole thing into here? Thanks. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#1195 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAA1hJAJE2xzudnNRKRiMO_dNbsThSxzks5tEloxgaJpZM4RM1OS> .

[remy]

I've got your email and managed to get a version of the code running, but I had to guess at the versions of dependencies and obviously I don't have your external dependencies (like the network.gz file). I couldn't replicate the problem though.

I suspect the cause is that your server isn't fully shutting down (cleanly) before it's started again. One thing that might help narrow down the issue is whether nodemon is able to restart the server after the uncaught ECONNRESET, or whether (though I doubt) this error is thrown from inside of nodemon.

Also, as a test: if you start nodemon and then change a file (without doing anything on your server), do you still get the same error?

In your code (the version you sent to me), if you stripped out all the routes, do you get the same error?

I can't think of where it might be coming from inside of nodemon, as the error is (IIRC) about network connections being reset and an error occuring when you try to reach that network. So that's why I suspect something inside your own code. I guess another test you could try is to use node to run your process, then ctrl+c, then start it immediately to see what you get (though it's possible the tear down is cleaner when just using node).

Let me know how you get on.

[roy7]

I'll do some tests to see what I can come up with.

Actually since I've not been using nodemon the last day or two, I just started it up and then did a 'rs' after a second or two, then a second 'rs', and the 2nd crashed. When this happens, nodemon exits to the command line.

[nodemon] 1.14.3
[nodemon] to restart at any time, enter rs
[nodemon] watching: test.js
[nodemon] starting node test.js
197 networks.
1464917 games.
listening on 8081
Current best hash 509e52021b827fcda2771ee3a81b5397d816a0218b3355a15de69b783477d495
[nodemon] starting node test.js
197 networks.
1464922 games.
listening on 8081
Current best hash 509e52021b827fcda2771ee3a81b5397d816a0218b3355a15de69b783477d495
events.js:183
throw er; // Unhandled 'error' event
^

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)

This was with

node node_modules/nodemon/bin/nodemon.js --watch test.js test.js >> log.test 2>&1

[roy7]

If my program "normally" crashes, nodemon will wait for a file to change and then try to restart the program. But in this situation where the crash happens because nodemon is trying to restart the process, nodemon itself always exits to the command line and is no longer running.

[roy7]

I copied the program over and ran it off a different port # to not interfere with the normal operation of things. If I just 'rs' over and over every few seconds, I can pretty much guarantee an eventual error as above. Is there any extra debugging options/flags I can set perhaps to help isolate with?

Ok "pretty much guarantee" is over stating it. It doesn't crash as easily as I'd like to reproduce it lol. The earlier test I got lucky it did it in the first few tries.

[roy7]

When it wants to cooperate:

jroy@sjeng:~/code/leela-zero-server$ node node_modules/nodemon/bin/nodemon.js --watch a a
[nodemon] 1.14.3
[nodemon] to restart at any time, enter rs
[nodemon] watching: a
[nodemon] starting node a
197 networks.
1465241 games.
listening on 8082
rs
Current best hash 509e52021b827fcda2771ee3a81b5397d816a0218b3355a15de69b783477d495
[nodemon] starting node a
197 networks.
1465241 games.
listening on 8082
Current best hash 509e52021b827fcda2771ee3a81b5397d816a0218b3355a15de69b783477d495
rs
[nodemon] starting node a
197 networks.
1465241 games.
listening on 8082
Current best hash 509e52021b827fcda2771ee3a81b5397d816a0218b3355a15de69b783477d495
rs
events.js:183
throw er; // Unhandled 'error' event
^

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)
jroy@sjeng:~/code/leela-zero-server$

[roy7]

I tried adding longjohn to my script, but it made no difference. So instead I added longjohn to node_modules/nodemon/bin/nodemon.js and that changes the error message to:

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)

at _destroy (internal/streams/destroy.js:34:15)
at Socket._destroy (net.js:561:3)
at Socket.destroy (internal/streams/destroy.js:32:8)
at Pipe.onread (net.js:615:17)

[remy]

Bit of a shot in the dark, but can you try with nodemon --no-update-notifier and run the same process, and report back?

[roy7]

node: bad option: --no-update-notifier

[roy7]

I'm trying to find a better solution than longjohn to find the problem spot. Re: mattinsler/longjohn#31.

[roy7]

Adding the process.on() catch to nodemon.js itself does catch the error and lets things continue.

rs
Caught exception: Error: read ECONNRESET
[nodemon] starting node a
212 networks.
1492972 games.
listening on 8082

[roy7]

I installed the debug package and run the script with DEBUG=*, not much more info but:

rs
nodemon bus emit: restart +2s
Caught exception: Error: read ECONNRESET
/home/jroy/code/leela-zero-server/node_modules/longjohn/dist/longjohn.js:192
throw e;
^

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)

at _destroy (internal/streams/destroy.js:34:15)
at Socket._destroy (net.js:561:3)
at Socket.destroy (internal/streams/destroy.js:32:8)
at Pipe.onread (net.js:615:17)

[roy7]

Comparing to restarts when it doesn't crash, the crash is between these two lines.

nodemon bus emit: restart +21s
nodemon bus.emit(exit) via SIGUSR2 +28ms

[remy]

If you're comfortable editing the nodemon source to test, can you find lib/monitor/run.js and comment out the line that reads bus.emit('error', error); - and re-run your tests?

[roy7]

Taking that line out seems to make the error reproducible every time I enter 'rs'.

[roy7]

Ok, not every time, but it seems very frequent now.

[remy]

Can you test with nodemon@1.14.6 and when you capture the error, can you include the full output from the point when the command was started to when you were thrown back to the prompt (using 1.14.6). Thanks.

[roy7]

jroy@sjeng:~/code/leela-zero-server$ DEBUG=* node --trace-warnings node_modules/nodemon/bin/nodemon.js  --watch a a
  nodemon bus new listener: reset (0) +0ms
  nodemon bus new listener: reset (0) +4ms
  nodemon bus new listener: quit (0) +31ms
  nodemon bus new listener: quit (0) +1ms
  nodemon bus new listener: restart (0) +0ms
  nodemon bus new listener: restart (0) +0ms
  nodemon bus new listener: reset (2) +2ms
  nodemon bus emit: reset +2ms
  nodemon resetting watchers +0ms
  nodemon reset +1ms
  nodemon config: dirs [ '/home/jroy/code/leela-zero-server/a' ] +90ms
[nodemon] 1.14.6
[nodemon] to restart at any time, enter `rs`
  nodemon bus new listener: error (0) +11ms
  nodemon bus new listener: error (0) +1ms
[nodemon] watching: a
[nodemon] starting `node a`
  nodemon spawning node a +11ms
  nodemon bus new listener: exit (0) +6ms
  nodemon bus new listener: exit (0) +0ms
  nodemon start watch on: a +1ms
  nodemon start watch on: /home/jroy/code/leela-zero-server/a +0ms
  nodemon ignored [ '**/.git',
  '**/.nyc_output',
  '**/.sass-cache',
  '**/bower_components',
  '**/coverage',
  '**/node_modules',
  re: /.*.*\/\.git|.*.*\/\.nyc_output|.*.*\/\.sass\-cache|.*.*\/bower_components|.*.*\/coverage|.*.*\/node_modules/ ] +0ms
  nodemon:watch watching dir: /home/jroy/code/leela-zero-server/a +34ms
  nodemon watch is complete +1ms
  express:application set "x-powered-by" to true +0ms
  express:application set "etag" to 'weak' +8ms
  express:application set "etag fn" to [Function: generateETag] +7ms
  express:application set "env" to 'development' +1ms
  express:application set "query parser" to 'extended' +0ms
  express:application set "query parser fn" to [Function: parseExtendedQueryString] +1ms
  express:application set "subdomain offset" to 2 +0ms
  express:application set "trust proxy" to false +0ms
  express:application set "trust proxy fn" to [Function: trustNone] +1ms
  express:application booting in development mode +1ms
  express:application set "view" to [Function: View] +0ms
  express:application set "views" to '/home/jroy/code/leela-zero-server/views' +0ms
  express:application set "jsonp callback name" to 'callback' +0ms
  express:application set "view engine" to 'pug' +1ms
  express:application set "trust proxy" to true +0ms
  express:application set "trust proxy fn" to [Function] +0ms
  express:router use '/' query +6ms
  express:router:layer new '/' +0ms
  express:router use '/' expressInit +2ms
  express:router:layer new '/' +0ms
  express:router use '/' urlencodedParser +0ms
  express:router:layer new '/' +1ms
  express:router use '/' <anonymous> +3ms
  express:router:layer new '/' +0ms
  express:router use '/view/player' serveStatic +1ms
  express:router:layer new '/view/player' +1ms
  express:router use '/viewmatch/player' serveStatic +0ms
  express:router:layer new '/viewmatch/player' +0ms
  express:router use '/view/wgo' serveStatic +1ms
  express:router:layer new '/view/wgo' +0ms
  express:router use '/viewmatch/wgo' serveStatic +0ms
  express:router:layer new '/viewmatch/wgo' +1ms
  express:router use '/best-network-hash' <anonymous> +27ms
  express:router:layer new '/best-network-hash' +1ms
  express:router use '/best-network' <anonymous> +0ms
  express:router:layer new '/best-network' +0ms
  express:router use '/best-network-old' <anonymous> +0ms
  express:router:layer new '/best-network-old' +0ms
  express:router:route new '/request-match' +1ms
  express:router:layer new '/request-match' +0ms
  express:router:route post '/request-match' +0ms
  express:router:layer new '/' +1ms
  express:router:route new '/submit-network' +0ms
  express:router:layer new '/submit-network' +0ms
  express:router:route post '/submit-network' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/submit-match' +1ms
  express:router:layer new '/submit-match' +0ms
  express:router:route post '/submit-match' +0ms
  express:router:layer new '/' +1ms
  express:router:route new '/submit' +0ms
  express:router:layer new '/submit' +0ms
  express:router:route post '/submit' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/' +0ms
  express:router:layer new '/' +1ms
  express:router:route get '/' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/get-task/:version(\\d+)' +0ms
  express:router:layer new '/get-task/:version(\\d+)' +0ms
  express:router:route get '/get-task/:version(\\d+)' +1ms
  express:router:layer new '/' +0ms
  express:router:route new '/view/:hash(\\w+)' +0ms
  express:router:layer new '/view/:hash(\\w+)' +0ms
  express:router:route get '/view/:hash(\\w+)' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/match-games/:matchid(\\w+)' +0ms
  express:router:layer new '/match-games/:matchid(\\w+)' +1ms
  express:router:route get '/match-games/:matchid(\\w+)' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/viewmatch/:hash(\\w+)' +0ms
  express:router:layer new '/viewmatch/:hash(\\w+)' +0ms
  express:router:route get '/viewmatch/:hash(\\w+)' +1ms
  express:router:layer new '/' +0ms
  express:router:route new '/data/elograph.json' +0ms
  express:router:layer new '/data/elograph.json' +0ms
  express:router:route get '/data/elograph.json' +0ms
  express:router:layer new '/' +0ms
246 networks.
1564069 games.
listening on 8082
Current best hash e5e72b39f3c201af91fcd0a6230da7756abab30b59eed33fb79205b3fe03a870
rs
  nodemon bus emit: restart +11s
events.js:183
      throw er; // Unhandled 'error' event
      ^

Error: read ECONNRESET
    at _errnoException (util.js:1024:11)
    at Pipe.onread (net.js:615:25)
jroy@sjeng:~/code/leela-zero-server$

[remy]

Okay, no clues…

Can you replicate using this as your script?

require('http').createServer((req, res) => res.end('ok')).listen(8000);

[roy7]

Wow. Actually, yes!

jroy@sjeng:/code/leela-zero-server$ cat > b
require('http').createServer((req, res) => res.end('ok')).listen(8000);
jroy@sjeng:/code/leela-zero-server$ DEBUG=* node --trace-warnings node_modules/nodemon/bin/nodemon.js --watch b b
nodemon bus new listener: reset (0) +0ms
nodemon bus new listener: reset (0) +6ms
nodemon bus new listener: quit (0) +82ms
nodemon bus new listener: quit (0) +0ms
nodemon bus new listener: restart (0) +0ms
nodemon bus new listener: restart (0) +0ms
nodemon bus new listener: reset (2) +15ms
nodemon bus emit: reset +4ms
nodemon resetting watchers +1ms
nodemon reset +0ms
nodemon config: dirs [ '/home/jroy/code/leela-zero-server/b' ] +186ms
[nodemon] 1.14.6
[nodemon] to restart at any time, enter rs
nodemon bus new listener: error (0) +7ms
nodemon bus new listener: error (0) +0ms
[nodemon] watching: b
[nodemon] starting node b
nodemon spawning node b +2ms
nodemon bus new listener: exit (0) +10ms
nodemon bus new listener: exit (0) +0ms
nodemon start watch on: b +0ms
nodemon start watch on: /home/jroy/code/leela-zero-server/b +1ms
nodemon ignored [ '/.git',
'/.nyc_output',
'/.sass-cache',
'/bower_components',
'/coverage',
'/node_modules',
re: /../.git|../.nyc_output|../.sass-cache|../bower_components|../coverage|../node_modules/ ] +1ms
nodemon:watch watching dir: /home/jroy/code/leela-zero-server/b +36ms
nodemon watch is complete +1ms
rs
nodemon bus emit: restart +2s
nodemon bus.emit(exit) via SIGUSR2 +42ms
nodemon bus emit: exit +0ms
[nodemon] starting node b
nodemon spawning node b +0ms
nodemon bus new listener: exit (1) +4ms
nodemon start watch on: b +0ms
nodemon:watch early exit on watch, still watching (1) +1ms
rs
nodemon bus emit: restart +2s
events.js:183
throw er; // Unhandled 'error' event
^

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)
jroy@sjeng:/code/leela-zero-server$

[remy]

Okay, in this case, something very strange is afoot!

So that we can rule out a socket from the child process (the simple http server), can you try with the following script instead:

console.log(__filename)

[roy7]

Can't seem to get that one to crash. I also notice it now says:

[nodemon] clean exit - waiting for changes before restart

which the http server version never does. So maybe there's an issue/bug with the node http server not exiting cleanly/properly?

[roy7]

I'm using Node 8.9.3 btw.

[remy]

Okay, I wonder if there's something special about the OS and the way nodemon is forking.

Can you try this command (with the http simple server code - where the filename is b):

DEBUG=* node --trace-warnings node_modules/bin/nodemon.js --watch b -x 'node b'

[remy]

Note that running the command with -x 'node b' internally nodemon is using a spawn command rather than a fork. I doubt if this is the cause, but it'll help rule it out (again, I can't replicate this at all on my machine, hence why the needle/haystack hunt!)

[roy7]

jroy@sjeng:/code/leela-zero-server$ DEBUG=* node --trace-warnings node_modules/nodemon/bin/nodemon.js --watch b -x 'node b'
nodemon bus new listener: reset (0) +0ms
nodemon bus new listener: reset (0) +3ms
nodemon bus new listener: quit (0) +20ms
nodemon bus new listener: quit (0) +0ms
nodemon bus new listener: restart (0) +0ms
nodemon bus new listener: restart (0) +0ms
nodemon bus new listener: reset (2) +3ms
nodemon bus emit: reset +3ms
nodemon resetting watchers +0ms
nodemon reset +1ms
nodemon config: dirs [ '/home/jroy/code/leela-zero-server/b' ] +67ms
[nodemon] 1.14.6
[nodemon] to restart at any time, enter rs
nodemon bus new listener: error (0) +7ms
nodemon bus new listener: error (0) +1ms
[nodemon] watching: b
[nodemon] starting node b
nodemon spawning node b +1ms
nodemon bus new listener: exit (0) +13ms
nodemon bus new listener: exit (0) +0ms
nodemon start watch on: b +0ms
nodemon start watch on: /home/jroy/code/leela-zero-server/b +1ms
nodemon ignored [ '/.git',
'/.nyc_output',
'/.sass-cache',
'/bower_components',
'/coverage',
'/node_modules',
re: /../.git|../.nyc_output|../.sass-cache|../bower_components|../coverage|../node_modules/ ] +0ms
nodemon:watch watching dir: /home/jroy/code/leela-zero-server/b +30ms
nodemon watch is complete +1ms
rs
nodemon bus emit: restart +1s
events.js:183
throw er; // Unhandled 'error' event
^

Error: read ECONNRESET
at _errnoException (util.js:1024:11)
at Pipe.onread (net.js:615:25)

[remy]

Okay…so, possibly the OS? Somehow? Are you running a Docker instance perchance? Otherwise I might be able to write a Dockerfile to get the exact version of unix flavour you're using (though I'm not very good at writing those!)

[roy7]

The server is running on a digital cloud provider, traceroute tells me it is www.hetzner.com. Any more info I can provide beyond uname -a?

4.4.0-101-generic #124-Ubuntu SMP Fri Nov 10 18:29:59 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Perhaps it's the older linux kernel or something.

[gcp]

It's Ubuntu 16.04 LTS on KVM.

[remy]

Okay, I'm now able to replicate using a Docker image using Ubuntu 16.04. I might be able to use this to iterate through a debugging process (finally!).

I'll post a gist with the files I'm using shortly.

[remy]

Okay, getting closer. If I comment out this line it doesn't blow up. But I can't work out why and what needs cleaning up to ensure this can re-connect properly.

[remy]

Got it. Took a while, but managed to find the right stream to hook the error handle on. Once (hopefully) the tests pass, I'll merge into master and it'll be live on 1.14.7

And if you want to support the project, you can here 👉 https://opencollective.com/nodemon/donate 😃

[remy]

Though…for some reason Travis CI is taking its merry time…

[roy7]

Thanks for digging into it enough to find and fix the problem! :) I sent in a small donation.

[remy]

Don't know why it took so long, but it was released 5 minutes ago. Thanks again.

[roy7]

BTW while you have your docker handy, I'll let you know that often nodemon won't restart my process even after I change the source file. That isn't a big deal compared to the fixed crashing, I re-attach screen and type 'rs' each time. But if you want I can make a new issue and help with debugging on that as well.

[remy]

I'll take a look, but I know that some other devs using the `-L` legacy watch method flag with nodemon and that occasional works around it. Will let you know if I find anything.

…

On Mon, 1 Jan 2018, 18:56 Jonathan Roy, ***@***.***> wrote: BTW while you have your docker handy, I'll let you know that often nodemon won't restart my process even after I change the source file. That isn't a big deal compared to the fixed crashing, I re-attach screen and type 'rs' each time. But if you want I can make a new issue and help with debugging on that as well. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#1195 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAA1hPQolii4krXQpOV7JK4ilU5bocpeks5tGSpGgaJpZM4RM1OS> .