Stream error not handled correctly

[Prinzhorn]

It's late, so maybe I'm on the wrong track (I come from newrelic/node-newrelic#76).

Anyway, the documentation says

Bunyan re-emits error events from the created WriteStream.

https://github.com/trentm/node-bunyan#stream-errors

Given this index.js

var bunyan = require('bunyan');
var log = bunyan.createLogger({name: "myapp"});

setInterval(function() {
    log.info("hi");
}, 500);

log.on('error', function(err, stream) {
    process.exit(1);
});

and then piping the output to a named pipe created by mkfifo mypipe using

node index.js > mypipe

I get the following error when I close the pipe

events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: write EPIPE
    at errnoException (net.js:901:11)
    at Object.afterWrite (net.js:718:19)

Shouldn't the program just exit without an error? I do handle the error event.

[Prinzhorn]

When I handle uncaughtException and let the process continue, I get this after the write EPIPE

Error: This socket is closed.
    at Socket._write (net.js:635:19)
    at doWrite (_stream_writable.js:219:10)
    at writeOrBuffer (_stream_writable.js:209:5)
    at Socket.Writable.write (_stream_writable.js:180:11)
    at Socket.write (net.js:613:40)
    at Logger._emit (/home/alexander/Documents/OSS/bunyan/node_modules/bunyan/lib/bunyan.js:757:22)
    at Logger.info (/home/alexander/Documents/OSS/bunyan/node_modules/bunyan/lib/bunyan.js:834:24)
    at null.<anonymous> (/home/alexander/Documents/OSS/bunyan/index.js:5:6)
    at wrapper [as _onTimeout] (timers.js:252:14)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)

which is exactly what I observed in newrelic/node-newrelic#76

[Prinzhorn]

Maybe I misunderstood the statement "Bunyan re-emits error events from the created WriteStream". I guess it only refers to the file streams that Bunyan created itself, at least that's what the source says (

node-bunyan/lib/bunyan.js

Line 372 in 06ade78

s.stream.on('error', function (err) {

)

If that's the case, does that mean we should handle other stream errors (specifically stdout/stderr) separately? If I re-emit the error event for streams as well (

node-bunyan/lib/bunyan.js

Line 363 in 06ade78

case 'stream':

) everything works as expected.

It would be really great to know, so that newrelic can handle the stdout error and exit gracefully.

[othiym23]

If this issue gets addressed, please let me know so I can fork and cherry-pick whatever chanes result. New Relic is version-locked to version 0.14.6 of Bunyan because I didn't want it to take the dependency on dtrace-provider because New Relic stuff can't have native dependencies (even if they're optional – compilation failures always generate support load). Thanks!

[wachunga]

I'm also experiencing this. Whenever I kill nodemon, I get such errors from bunyan.

>         throw er; // Unhandled 'error' event
              ^
Error: This socket is closed.
    at Socket._write (net.js:635:19)
    at doWrite (_stream_writable.js:219:10)
    at writeOrBuffer (_stream_writable.js:209:5)
    at Socket.Writable.write (_stream_writable.js:180:11)
    at Socket.write (net.js:613:40)
    at Logger._emit (/Users/davidhirtle/dev/src/node-app-context/node_modules/bunyan/lib/bunyan.js:693:16)
    at Logger.fatal (/Users/davidhirtle/dev/src/node-app-context/node_modules/bunyan/lib/bunyan.js:731:10)
    at process.<anonymous> (/Users/davidhirtle/dev/src/node-app-context/error/index.js:11:9)
    at process.EventEmitter.emit (events.js:95:17)
    at process._fatalException (node.js:272:26)

[basickarl]

I'm also getting this error:

karl@karl-laptop:~/www/instantynode/src$ node app.js | bunyan -o short
bunyan: command not found
events.js:154
      throw er; // Unhandled 'error' event
      ^

Error: write EPIPE
    at Object.exports._errnoException (util.js:856:11)
    at exports._exceptionWithHostPort (util.js:879:20)
    at WriteWrap.afterWrite (net.js:763:14)

To recreate the error just uninstall bunyan then try and run the command.

[yveslange]

@basickarl did you install bunyan globally ?

npm install -g bunyan

Look at the second line of the error: bunyan: command not found

[deadbeef84]

I'm also getting Error: This socket is closed when piping, I took a quick look at the bunyan cli source code and it appears to look for this error, however in node 6.0.0 this error message was changed and the ending period was removed, so now the test in bunyan fails. Anyone willing to fix this or do you want me to send a PR?

[trentm]

@deadbeef84 The "This socket is closed" thing is in the bunyan CLI. The OP is about the bunyan module. So I believe these are separate issues. It would be helpful to have a separate ticket (with repro details) for what you are seeing. I'm also curious if recent changes in #246 affect what you see. Also I have some not-quite-yet-commited work around bunyan CLI exit handling that might be relevant as well.

[trentm]

It has been years, so I assume @Prinzhorn that you have moved on. :) Sorry for the delay. However, for completeness, and because I've been handling other EPIPE and exit-handling related Qs for bunyan of late (as I've improved in my understanding), I'll answer the OP here.

Others on this thread, if you still have issues with the latest Bunyan, please open new tickets and I'll try to answer them there. Note that the issues are different with "bunyan the library" usage vs "bunyan the CLI" usage.

---

At the time of the OP, the current version of bunyan was 0.22.0. Since then, the behaviour of EPIPE handling with bunyan the library has not changed. However, since then the reemitErrorEvents option has been added to Bunyan streams and https://github.com/trentm/node-bunyan#stream-errors has been updated. This was added in version 1.7.0 as part of pull #318 (changelog entry).

Bunyan re-emitting of stream errors was initially added only for Bunyan streams of type=file. Writing to process.stdout (Bunyan's default) is a Bunyan stream of type="stream". To re-emit errors on that stream requires the explicit reemitErrorEvents: true. If we change the original code sample to:

var bunyan = require('bunyan');
var log = bunyan.createLogger({
    name: "myapp",
    streams: [
        {
            stream: process.stdout,
            reemitErrorEvents: true
        }
    ]
});

setInterval(function() {
    log.info("hi");
}, 500);

log.on('error', function(err, stream) {
    process.exit(1);
});

Then it works as intended. In one terminal:

$ cat read-from-mypipe.sh
#!/bin/bash
PIPE=$1
trap "rm -f $PIPE" EXIT

if [[ ! -p $PIPE ]]; then
    mkfifo $PIPE
fi

while true
do
    if read line <$PIPE; then
        echo $line
    fi
done

$ bash read-from-mypipe.sh mypipe
{"name":"myapp","hostname":"danger0.local","pid":25580,"level":30,"msg":"hi","time":"2017-05-16T06:37:08.407Z","v":0}
{"name":"myapp","hostname":"danger0.local","pid":25580,"level":30,"msg":"hi","time":"2017-05-16T06:37:08.918Z","v":0}
{"name":"myapp","hostname":"danger0.local","pid":25580,"level":30,"msg":"hi","time":"2017-05-16T06:37:09.424Z","v":0}
{"name":"myapp","hostname":"danger0.local","pid":25580,"level":30,"msg":"hi","time":"2017-05-16T06:37:09.930Z","v":0}
^C

and in a second terminal:

$ node issue108.js >mypipe

$ echo $?
1