Node-bunyan: Custom streams and log levels confusion

[mkozjak]

For the life of me, I cannot see why is log.info ending up in both InfoStream and DebugStream if the log level is properly set.
log_default.info works as expected. Can anyone help?

var bunyan = require('bunyan');

function InfoStream() {}

InfoStream.prototype.write = function(data) {
  process.stdout.write("INFO: " + data)
}

function DebugStream() {}

DebugStream.prototype.write = function(data) {
  process.stdout.write("DEBUG: " + data)
}

var log = bunyan.createLogger({
  name: "logger1",
  streams: [{
    level: "info",
    stream: new InfoStream()
  }, {
    level: "debug",
    stream: new DebugStream()
  }]
})

var log_default = bunyan.createLogger({
  name: "logger2"
})

log.level(bunyan.INFO)
log.info("info me")
log.debug("debug me")

log_default.level(bunyan.INFO)
log_default.info("default info me")
log_default.debug("default debug me")

/*
Outputs:

INFO: {"name":"logger1","hostname":"Air","pid":25367,"level":30,"msg":"info me","time":"2016-07-03T10:15:44.640Z","v":0}
DEBUG: {"name":"logger1","hostname":"Air","pid":25367,"level":30,"msg":"info me","time":"2016-07-03T10:15:44.640Z","v":0}
{"name":"logger2","hostname":"Air","pid":25367,"level":30,"msg":"default info me","time":"2016-07-03T10:15:44.643Z","v":0}

*/

[mkozjak]

Here's the full debug bunyan log:

XXX: Logger start: { name: 'logger1',
  streams: 
   [ { level: 'info', stream: InfoStream {} },
     { level: 'debug', stream: DebugStream {} } ] }
XXX: Logger:  Logger {
  domain: null,
  _events: {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _level: 20,
  streams: 
   [ { level: 30,
       stream: InfoStream {},
       type: 'stream',
       raw: false,
       closeOnExit: false },
     { level: 20,
       stream: DebugStream {},
       type: 'stream',
       raw: false,
       closeOnExit: false } ],
  serializers: null,
  src: false,
  fields: {} }
XXX: Logger start: { name: 'logger2' }
XXX: Logger:  Logger {
  domain: null,
  _events: {},
  _eventsCount: 0,
  _maxListeners: undefined,
  _level: 30,
  streams: 
   [ { type: 'stream',
       stream: [Object],
       closeOnExit: false,
       level: 30,
       raw: false } ],
  serializers: null,
  src: false,
  fields: {} }
XXX: writing log rec "info me" to "stream" stream (30 <= 30): {"name":"logger1","hostname":"Air","pid":30791,"level":30,"msg":"info me","time":"2016-07-03T16:07:10.754Z","v":0}
INFO: {"name":"logger1","hostname":"Air","pid":30791,"level":30,"msg":"info me","time":"2016-07-03T16:07:10.754Z","v":0}
XXX: writing log rec "info me" to "stream" stream (20 <= 30): {"name":"logger1","hostname":"Air","pid":30791,"level":30,"msg":"info me","time":"2016-07-03T16:07:10.754Z","v":0}
DEBUG: {"name":"logger1","hostname":"Air","pid":30791,"level":30,"msg":"info me","time":"2016-07-03T16:07:10.754Z","v":0}
20
XXX: writing log rec "debug me" to "stream" stream (20 <= 20): {"name":"logger1","hostname":"Air","pid":30791,"level":20,"msg":"debug me","time":"2016-07-03T16:07:10.759Z","v":0}
DEBUG: {"name":"logger1","hostname":"Air","pid":30791,"level":20,"msg":"debug me","time":"2016-07-03T16:07:10.759Z","v":0}
XXX: writing log rec "default info me" to "stream" stream (30 <= 30): {"name":"logger2","hostname":"Air","pid":30791,"level":30,"msg":"default info me","time":"2016-07-03T16:07:10.759Z","v":0}
{"name":"logger2","hostname":"Air","pid":30791,"level":30,"msg":"default info me","time":"2016-07-03T16:07:10.759Z","v":0}

[mkozjak]

Are we supposed to handle log entry levels in custom Streams on our own no matter the defined level in each?

[trentm]

@mkozjak Calling log.level(bunyan.INFO) sets the level of _all streams_ on that logger to "info" level. This demonstrates that:

//var bunyan = require('bunyan');
var bunyan = require('./');

function InfoStream() {}
InfoStream.prototype.write = function(data) {
  process.stdout.write("INFO: " + data)
}

function DebugStream() {}
DebugStream.prototype.write = function(data) {
  process.stdout.write("DEBUG: " + data)
}

var log = bunyan.createLogger({
  name: "logger1",
  streams: [{
    level: "info",
    stream: new InfoStream()
  }, {
    level: "debug",
    stream: new DebugStream()
  }]
})

log.streams.forEach(function (s) {
    console.log('stream %s level before: %s',
        s.stream.constructor.name, s.level);
});
log.level(bunyan.INFO)
log.streams.forEach(function (s) {
    console.log('stream %s level after: %s',
        s.stream.constructor.name, s.level);
});

log.info("info me")
log.debug("debug me")

which results in

$ node issue421.js  | bunyan
stream InfoStream level before: 30
stream DebugStream level before: 20
stream InfoStream level after: 30
stream DebugStream level after: 30     // <--- note here that this is now info level
INFO: {"name":"logger1","hostname":"danger0.local","pid":48431,"level":30,"msg":"info me","time":"2016-07-05T05:33:58.726Z","v":0}
DEBUG: {"name":"logger1","hostname":"danger0.local","pid":48431,"level":30,"msg":"info me","time":"2016-07-05T05:33:58.726Z","v":0}

Please re-open if I misunderstood your question.

[mkozjak]

@trentm: No matter what, even if I don't call log.level(bunyan.INFO) (code), the output based on log.info() is still the same:

INFO: {"name":"logger1","hostname":"Mini","pid":66539,"level":30,"msg":"info me","time":"2016-07-05T07:35:40.971Z","v":0}
DEBUG: {"name":"logger1","hostname":"Mini","pid":66539,"level":30,"msg":"info me","time":"2016-07-05T07:35:40.971Z","v":0}

Why is the DebugStream.write function ever called here in this scenario? The default 'main' level is 30, the DebugStream level is 20, but DebugStream.write is triggered (???).

In my opinion, DebugStream.write should not be triggered if I called log.info(), since it's on level 'debug'.
If it was on log.level debug, then it'd be okay for it to get called, along with InfoStream.write and the rest of the upstream levels (warn, error, fatal), obviously.

So I don't really understand how to use it. Sorry if I'm ignorant. :)

[trentm]

Ah, there is a second misunderstanding here. Saying "level": "debug" is intended to mean "all log records at level debug and above". This pull updated docs to attempt to clarify this: https://github.com/trentm/node-bunyan/pull/321
Related tickets were: #305 #320 #339 #394

[mkozjak]

@trentm: This is nothing I already didn't know. Can you see my last reply and answer why is the DebugStream's write method ever triggered?

Saying "level": "debug" is intended to mean "all log records at level debug and above".

Yeah, and I called log.info and DebugStream.write was triggered. The stream where DebugStream was instantiated was set to "debug", so log.info() should not trigger that stream at all.

Can you clarify that?
If you see what I'm trying to accomplish, can you create a sample code that works as expected?

Thank you in advance!

[voxpelli]

The info level is one level above debug, the only level below debug is trace so only trace logs will get excluded from DebugStream. See: https://github.com/trentm/node-bunyan/blob/master/README.md#levels

[mkozjak]

@voxpelli: Yeah, and why is debug not excluded when log.info() is called? Imagine only log.info() is ever called. We have already talked about this.

https://gist.github.com/mkozjak/b73e9b47be4bc9bd39d48e7029447e19

From examples above you can see that the default logger (without custom streams) behaves as expected, but once you put your stuff like in this gist, it does not.

The main issue here that I still haven't got an answer to yet is why is the stream that's set to debug getting triggered if I call log.info(), which is above the debug. @trentm @voxpelli

My code is basically copied from the docs:

var log = bunyan.createLogger({
  name: 'myapp',
  streams: [
    {
      level: 'info',
      stream: process.stdout            // log INFO and above to stdout
    },
    {
      level: 'error',
      path: '/var/tmp/myapp-error.log'  // log ERROR and above to a file
    }
  ]
});

It's just that instead of 'error' I have 'debug'. See comments about the info stream: "// log INFO and above to stdout"

ABOVE.

The same should apply to the debug. "log DEBUG and above". If you call log.info() (which is ABOVE debug), it's expected that the below level streams (debug, in my case) are never called. This is not the case in my code and I don't know why.

@trentm: Half of those referenced tickets are not relevant to this issue. Please, reopen this one.

[voxpelli]

@mkozjak It's the other way around to what you're describing. It's the _stream_ that include all log calls at debug and above, not the _logging call_ that include all streams at it's level and above.

So when you do a log.info() all streams takes a look at that log point and checks: Is this below the level that has been defined for my stream? If so: Disregard it. If not: Then include it.

For a stream set up to to the debug log level it will get the info-level log point, see that the level of that log point is above the log level set on its stream and therefore include that log point.

[mkozjak]

This is confusing to the bone. Hence so many tickets are there for the same reason.

@voxpelli: Can you provide me with the working code? I want two streams. One for debug and one for info. Custom streams.

If I call log.info(), I DO NOT want the debug stream to work. If I call log.debug(), I WANT both to get called.
So, if the GLOBAL level is info, I want only info() to work. If the GLOBAL level is debug, I want both to work.

[mkozjak]

Look at Bristol. I have managed to get this working in two minutes.

var log = require('bristol');

log.addTarget(function(options, severity, date, message) {
    console.log("DEBUG: ", message)
}).withHighestSeverity('debug')

log.addTarget(function(options, severity, date, message) {
    console.log("INFO: ", message)
}).withHighestSeverity('info')

log.info("INFO MESSAGE")
log.debug("DEBUG MESSAGE")

The output is:

INFO:  {"message":"INFO MESSAGE","date":"2016-07-06 12:12:41","severity":"info","file":"/opt/dev/tests/node.js/brist.js","line":"11"}
DEBUG:  {"message":"DEBUG MESSAGE","date":"2016-07-06 12:12:41","severity":"debug","file":"/opt/dev/tests/node.js/brist.js","line":"12"}
INFO:  {"message":"DEBUG MESSAGE","date":"2016-07-06 12:12:41","severity":"debug","file":"/opt/dev/tests/node.js/brist.js","line":"12"}

[kushdilip]

@mkozjak It might be too late but I think what you were looking for is in examples directory.
Here it is https://github.com/trentm/node-bunyan/blob/master/examples/rot-specific-levels.js

You can modified above code as per your wish to redirect logs somewhere else.