Node-bunyan: EPIPE errors with ctrl+c using CLI

[brandonmp]

extending my comment in issue #246

sample repo: https://github.com/brandonmp/bunyan-ctrl-c-issue. I added some comments, but just let me know if anything's not clear.

node 7.1/npm 4.2/ubuntu 16.10/bunyan 1.8.9 & .10

My app pipes output to the bunyan CLI, i.e., node index.js | bunyan

I'm using a simple kill switch pattern to gracefully shutdown async workers (single-threaded, not clusters). In bunyan 1.8.5, this pattern worked, but as of 1.8.9/10, it's throwing an EPIPE error when I press ctrl-c

throw er; // Unhandled 'error' event
      ^

Error: write EPIPE
    at exports._errnoException (util.js:1034:11)
    at WriteWrap.afterWrite [as oncomplete] (net.js:812:14

Ignoring EPIPE errors results in a different

// code
 process.stdout.on('error', err => {
    if (err.code === 'EPIPE') {
      // ignore
    } else {
      throw err;
    }
  });

// err
Error: This socket is closed
    at Socket._writeGeneric (net.js:691:19)
    at Socket._write (net.js:742:8)
    at doWrite (_stream_writable.js:329:12)
    at writeOrBuffer (_stream_writable.js:315:5)
    at Socket.Writable.write (_stream_writable.js:241:11)
    at Socket.write (net.js:669:40)
    at Logger._emit (/home/bmp/storage/code/bunyan-ctrl-c-issue/node_modules/bunyan/lib/bunyan.js:923:22)
    at Logger.info (/home/bmp/storage/code/bunyan-ctrl-c-issue/node_modules/bunyan/lib/bunyan.js:1045:24)
    at Timeout.setTimeout [as _onTimeout] (/home/bmp/storage/code/bunyan-ctrl-c-issue/index.js:40:13)
    at ontimeout (timers.js:386:14)

[zbjornson]

(I'm not a bunyan expert, but hopefully I can help a bit since I submitted the revert PR that caused this, without communicating wrong info!)

I can reproduce both errors (the This socket is closed error is the same one I hit in the other issue btw), and I think the socket error is the one to pursue. That is, do ignore EPIPE for the reasons discussed in #246, and handle the socket error (maybe with a PR to bunyan.js, since others are hitting it in #108).

If you ignore the socket error with something like

process.stdout.on('error', err => {
  if (err.code === 'EPIPE' || err.toString() === 'Error: This socket is closed') {
    // ignore
  } ...

then the message is gone and your app closes gracefully. However, because Bunyan CLI terminates as soon as SIGTERM is received, you lose your shutdown messages -- I added process.on("exit", () => { process.stderr.write("CLI EXIT"); }) to bunyan CLI:

$ node index.js | bunyan
[2017-04-11T19:18:07.582Z]  INFO: issue-demo/184 on BJORNSON-DT: TASK STARTED
[2017-04-11T19:18:07.583Z]  INFO: issue-demo/184 on BJORNSON-DT: TASK STARTED
[2017-04-11T19:18:07.584Z]  INFO: issue-demo/184 on BJORNSON-DT: TASK STARTED
[2017-04-11T19:18:07.584Z]  INFO: issue-demo/184 on BJORNSON-DT: TASK STARTED
[2017-04-11T19:18:07.584Z]  INFO: issue-demo/184 on BJORNSON-DT: TASK STARTED
^CCLI EXIT
$

I'm not positive if it's viable for bunyan.js to ignore "This socket is closed[.]" on all streams that are handed to it. This error should only happen on stdout since that's what the CLI takes. Bunyan CLI has explicit handling but it owns the stream. Maybe @trentm has a preferred resolution.

Short of making a change to bunyan.js, you can listen and ignore the ignore in process.stdout.on("error") in the same way that you ignore EPIPE (as above).

Hope that helps!

[trentm]

@brandonmp Sorry for the delay. Thanks for creating the example repo! Here is my read of what is happening with your script.

For starters, the same thing happens when piping to any other command (that exits on SIGINT, aka Ctrl+C). E.g. when running node index.js | cat. That helps eliminate that the bunyan CLI is part of the runtime issue when you get "Error: This socket is closed".

I have this patch on your index.js:

diff --git a/index.js b/index.js
index b2fd4f4..74cc72e 100644
--- a/index.js
+++ b/index.js
@@ -6,7 +6,7 @@ const MAX_WORKERS = 5;
 let IS_KILLSWITCH_ACTIVE = false;
 let NUM_WORKERS_SHUTDOWN = 0;

-const SHOULD_IGNORE_EPIPE = false;
+const SHOULD_IGNORE_EPIPE = true;

 const log = bunyan.createLogger({
   name: 'issue-demo',
@@ -33,10 +33,12 @@ const ignoreEpipe = () => {

 /*** mimic async task */
 const doTask = () => {
+  console.error('XXX TASK STARTED');
   log.info('TASK STARTED');
   return new Promise(resolve =>
     setTimeout(
       () => {
+        console.error('XXX TASK COMPLETED');
         log.info('TASK COMPLETED');
         resolve();
       },

Here is an annotated run:

$ node index.js | cat
XXX TASK STARTED
{"name":"issue-demo","hostname":"danger0.local","pid":76585,"level":30,"msg":"TASK STARTED","time":"2017-05-03T06:14:20.113Z","v":0}
XXX TASK STARTED
{"name":"issue-demo","hostname":"danger0.local","pid":76585,"level":30,"msg":"TASK STARTED","time":"2017-05-03T06:14:20.115Z","v":0}
XXX TASK STARTED
{"name":"issue-demo","hostname":"danger0.local","pid":76585,"level":30,"msg":"TASK STARTED","time":"2017-05-03T06:14:20.116Z","v":0}
XXX TASK STARTED
{"name":"issue-demo","hostname":"danger0.local","pid":76585,"level":30,"msg":"TASK STARTED","time":"2017-05-03T06:14:20.116Z","v":0}
XXX TASK STARTED
{"name":"issue-demo","hostname":"danger0.local","pid":76585,"level":30,"msg":"TASK STARTED","time":"2017-05-03T06:14:20.116Z","v":0}
^C

I hit ^C soon after all the tasks were started. The shell passes SIGINT to all the processes in the pipeline and cat (or bunyan) quickly exit. However, index.js do not exit. After the 0-10s timeout (Math.random() * 10 * 1000) the first "TASK COMPLETED":

XXX TASK COMPLETED
/Users/trentm/tmp/bunyan-ctrl-c-issue/index.js:29
      throw err;
      ^

Error: This socket is closed
    at Socket._writeGeneric (net.js:680:19)
    at Socket._write (net.js:731:8)
    at doWrite (_stream_writable.js:334:12)
    at writeOrBuffer (_stream_writable.js:320:5)
    at Socket.Writable.write (_stream_writable.js:247:11)
    at Socket.write (net.js:658:40)
    at Logger._emit (/Users/trentm/tmp/bunyan-ctrl-c-issue/node_modules/bunyan/lib/bunyan.js:923:22)
    at Logger.info (/Users/trentm/tmp/bunyan-ctrl-c-issue/node_modules/bunyan/lib/bunyan.js:1045:24)
    at Timeout.setTimeout (/Users/trentm/tmp/bunyan-ctrl-c-issue/index.js:42:13)
    at ontimeout (timers.js:365:14)

This immediately raises an "error" event on process.stdout because the log.info('TASK COMPLETED'); is attempting to write to stdout. However, stdout is a pipe to the now closed cat (or bunyan) process.

The registered "error" handler throws the err:

  process.stdout.on('error', err => {
    if (err.code === 'EPIPE') {
      // ignore
    } else {
      throw err;    // <---- here
    }

And we get an unhandle exception crash.

Because you are piping to a program that will exit on SIGINT, and because the shell will pass the SIGINT to all the processes... you unfortunately cannot have graceful exit handling that writes to stdout. An alternative might be to redirect to a file, e.g. node index.js > run.log 2>&1, and then tail -f run.log | bunyan to watch a Bunyan-rendered version of the output.

[zbjornson]

Because you are piping to a program that will exit on SIGINT, and because the shell will pass the SIGINT to all the processes... you unfortunately cannot have graceful exit handling that writes to stdout.

Well, you can, if you ignore the error in the same way that the CLI does and as I showed in my comment. (But Bunyan can't do anything once it has closed of course.)

[trentm]

@zbjornson Yes. Fair enough. :)

[r4j4h]

Just wanted to add that I found creating a secondary "emergency" logger that was hooked to process.stderr works to maintain node-bunyan and logging even in this caught case.

To be clear, normal logged output is caught from the closed stdout, but stderr remains open and does not get filtered by bunyan - so the emergency logs come through with bunyan as if it were not running, and they still come through (unless filtered out) run normally all the same.

This was a little more convenient than letting them disappear when bunyan CLI is used for pretty output, and more convenient than using a file for some cases or all cases and tailing it through Bunyan CLI.

[servel333]

Adding this to my node script seems to at least make the script not crash when STDOUT closes. It will glob up any error, but it does fix this problem.

process.stdout.on('error', function(e){});

This also seems to work and I think it's a bit better.

const stream = require('stream');
var tryStdout = new stream.Writable();
tryStdout._write = function (chunk, encoding, done) {
  try{
    process.stdout._write(chunk, encoding, function(){ done(); });
  }
  catch(ignore){ done(); }
};

const logger = bunyan.createLogger({
  name: 'server',
  streams: [
    { stream: tryStdout },
  ],
});