Node-bunyan: log functions should offer a slot for callback function

[bpytlik]

The problem I'm encountering is that testing my logging is difficult because the current log interface assumes that the log call is either synchronous or that no one cares when the log has been written. Especially when testing using a log writer that is asynchronous, that assumption is problematic. It would be great if there was a way to specify a callback function when calling .trace/.info/etc... that's called once the log has been actually stored.

[trentm]

You'd want that _per log.{info,debug,...}() call_? I mean, as opposed to some reliable way to "close" a logger at the end and ensure that they are written (which is https://github.com/trentm/node-bunyan/issues/37).

I'd love to hear your use case to help motivate expanding the Bunyan API for something like this. For any plain old logging usage (at least that I've ever done) I can't imagine wanting to do something like this.

log.info("blah blah", function (err) { /* okay done writing that log record */ });

[trentm]

THinking out loud. Perhaps a <Logger instance>.on('emit', <callback>) "emit" event for each emitted log record or something.

[bpytlik]

I would want it per log.{info...} call, which is a bit different than #37. The biggest use case is for testing where I want to test that a log has been written as expected. (Just for clarification, I'm doing this testing because I've implemented my own stream writer to log to another kind of storage medium and I want to be sure that's doing what I think it should.) Any approach other than a callback-like approach (I think) has the problem of potential race conditions. I'll admit that I'm less clear on what should happen with multiple streams and callbacks, but I'd be happy to explore the space if it's interesting.

The second use case is one fairly particular to my use which is that I'm controlling a system with my node program. When a user requests a reboot or shutdown of the system, I want to be completely certain that the request is logged (and has hit permanent storage) before essentially pulling the power on the box.

The emit approach might work. I'd really need a way then to attach an id to a call to log.{info...} so that I'd know whether the log entry that caused the emit to happen is the one I'm interested in or one that happened for some other reason.

[trentm]

For your first case (testing), could you (a) add a unique id to each of
your log calls (generate a UUID or something and put in an 'id' or 'uuid'
field) and (b) put the code on your custom stream writer to ensure those
are written? So you testing would be something like:

var id = genUuid()
log.info({id: id}, "blah blah")
myCustomeStream.waitForId(id, function (err) { ... })

Granted that is more of a pain.

To be sure that a log record is written to permanent storage is specific to
the stream type. Say for a _file_ stream... you need to in general wait for
a 'drain' on the write call (
http://nodejs.org/api/stream.html#stream_writable_write_chunk_encoding_callback_1).
That's out of scope for Bunyan's writing. IOW, mostly this is a job for the
particular stream. Bunyan is (at least currently) synchronous on calling
stream.write(record).

On Fri, Jun 28, 2013 at 1:28 PM, bpytlik [email protected] wrote:

I would want it per log.{info...} call, which is a bit different than #37https://github.com/trentm/node-bunyan/issues/37.
The biggest use case is for testing where I want to test that a log has
been written as expected. (Just for clarification, I'm doing this testing
because I've implemented my own stream writer to log to another kind of
storage medium and I want to be sure that's doing what I think it should.)
Any approach other than a callback-like approach (I think) has the problem
of potential race conditions. I'll admit that I'm less clear on what should
happen with multiple streams and callbacks, but I'd be happy to explore the
space if it's interesting.

The second use case is one fairly particular to my use which is that I'm
controlling a system with my node program. When a user requests a reboot or
shutdown of the system, I want to be completely certain that the request is
logged (and has hit permanent storage) before essentially pulling the power
on the box.

The emit approach might work. I'd really need a way then to attach an id
to a call to log.{info...} so that I'd know whether the log entry that
caused the emit to happen is the one I'm interested in or one that happened
for some other reason.

—
Reply to this email directly or view it on GitHubhttps://github.com/trentm/node-bunyan/issues/95#issuecomment-20212428
.

Trent Mick

[bpytlik]

The approach for testing is interesting and might be workable.

Perhaps we mean different things but I don't think that the FileStream or RotatingFileStream (for example) is synchronous. The write function (http://nodejs.org/api/stream.html#stream_writable_write_chunk_encoding_callback_1) takes a callback. The call to write in _emit doesn't pass a callback nor check the return from write. I think this means that

• If the write returns false, then the buffer hasn't been flushed
• If the write fails (because of ENOSPACE for example) the call to write and _emit will have already returned so there would be no way to catch the error. My hope is that if a callback to write was provided, that callback would be called with the error instead of the error propagating uncontrollably. (Perhaps I'm confused as I'm not an expert on how node handles IO, so please correct me if I'm wrong.)

To me, that means that Bunyan is asynchronous wrt calling stream.write.

I agree that determining when an arbitrary stream has written a log permanently is out of scope for Bunyan's writing. I disagree that it's out of Bunyan's scope to provide a mechanism by which a stream can convey to the user that a log has been stored permanently (via a callback for example). I'd also disagree that it's out of scope for Bunyan to provide that infrastructure for the streams that are included (like file streams), especially when the lack of a callback option suggests that the functions are synchronous.

[binarykitchen]

I would welcome this too because I want to send anything above the warning level by email as well.

[qubyte]

fwiw, winston offers this slot, and it's useful for things such as:

server.once('error', function(err){
    function exit() {
        process.exit(1);
    }

    if (err.code === 'EADDRINUSE') {
        logger.error('Port already in use by another app. Server shutting down.', exit);
    } else {
        logger.error({err: err}, 'Express server error.', exit);
    }
});

Where you _need_ to be certain that the log has happened before exiting the process.

[ryanbreen]

+1 to this.

As far as I can tell, the lack of this feature makes it impossible to rely on bunyan for logging from implicitly short-running stuff like AWS Lambda jobs: if I want to use, say, bunyan-logentries to track activity in a Lambda function, I see some or none of the log messages unless I introduce a setTimeout that a) still can't guarantee I'll have enough time for messages to be flushed and b) arbitrarily inflates my Lambda job runtimes (and thus costs).

[syrnick]

+1

[cmmartin]

An example of a use case where callbacks or promises are really important...

process.on('uncaughtException', e => {
    logger.fatal(e)
    process.exit(1)
})

This log will never be written, because we must kill the process or risk our application running in an unstable state. Currently, we could do this...

process.on('uncaughtException', e => {
    logger.fatal(e)
    setTimeout(() => process.exit(1), 1000)
})

And then hope that the logs are written in 1 second (or whatever arbitrary amount of time) and also hope that we don't service any new requests in that time while our application is unstable. We can remove the risk of not writing our logs before killing the process and minimize the uptime of the application in an unstable state with a callback or promise...

process.on('uncaughtException', e => {
    logger.fatal(e, { onComplete: () => process.exit(1) })
})

Promises are better...

process.on('uncaughtException', e => {
    logger.fatal(e).then(() => process.exit(1))
})

[oztune]

+1

[saikojosh]

+1

[analytically]

:+1:

[juanstiza]

👍

[iMasoud]

+1

[cmawhorter]

-1.

What happens when the stream endpoint goes down? Does your uncaughtException keep retrying indefinitely? Does your lambda keep retrying until aws kills it at the timeout? What happens to the log entry then?

Having this feature mitigates the problem but doesn't solve it and you still need to.

FWIW: Couldn't this just be implemented by writing a custom stream that prevents the process from exiting until it (the custom stream) guarantees the write was successful? That's what I did with an AWS SNS writable stream wrapper for bunyan. log => sns retry N times => fall back to email. Prevent the process from exiting if there are log entries that haven't been flushed.

[cmmartin]

@cmawhorter If you look at my code example in my comment above, it would be trivial to implement retry x amount of times and fall back to email. I'm not sure that is within the scope of this library, but the changes requested here in no way prevent you from doing it. In fact, they make it possible while it currently is not after an application crash.

[lancespeelmon]

+1 we should be able to use bunyan for the use case without a setTimeout:

process.on('uncaughtException', e => {
    logger.fatal(e)
})

[alohaninja]

setTimeout(() => process.exit(1), 3000); worked to flush bunyan logs for me. There really should be a exported method to trigger the flush as this is rather hacky.