Winston: Log messages written in order?

[richb-hanover]

Is it possible to have winston log its messages to a transport in order? It's hard to read log files that aren't sequential.

For example, I have a log output that included a date/time with milliseconds. (See below)

Is there a way to specify that each of the log messages be written in the order they occur? Thanks.

2016-02-25 21:34:07.671 INFO  ...
2016-02-25 21:34:07.692 INFO  ...
2016-02-25 21:34:07.690 DEBUG  ...
2016-02-25 21:34:07.692 INFO  ...
2016-02-25 21:34:07.691 DEBUG  ...
2016-02-25 21:34:07.692 DEBUG  ...
2016-02-25 21:34:07.692 DEBUG  ...

NB: The code that generates the timestamps is at: https://github.com/winstonjs/winston/issues/802

[codercurtis]

+1. I'm not sure if this is something everyone already knows about an accepts, but I'm running into this too when doing a lot of async stuff.

[alebacca89]

I've the the same problem..

[reyazucar]

me too,
i am not sure if the problem is the diferent level of log

[Jeff-Lewis]

@richb-hanover can you share the exact code you are using to make the example logs above?

My guess is this can happen if somewhere in the call stack of INFO it uses process.nextTick and the DEBUG call stack uses setImmediate, or something of this nature.

nextTick vs setImmediate, visual explanation

process.nextTick vs setImmediate

[richb-hanover]

@Jeff-Lewis The short answer is, No. The code I'm using is a deeply welded into a bunch of other stuff. It isn't sufficiently distracting that it's worth building a test case.

I'm content to know that a) it's not something I'm "doing wrong"; b) it might be related to nextTick vs setImmediate, and c) I can live with the occasional out-of-order log messages.

But if any of the others who gave a +1 to this can come up with a test case, please go ahead!

[zamnuts]

@richb-hanover This is an issue with the default logging levels and their relationship with stdout and stderr. The culprit is:
https://github.com/winstonjs/winston/blob/2.2.0/lib/winston/transports/console.js#L118-L122
and the associated option is declared at:
https://github.com/winstonjs/winston/blob/2.2.0/lib/winston/transports/console.js#L34

The default stderr log levels are error and debug (defined as ['error','debug']), all other levels are routed to stdout. On the console, stdout and stderr are consolidated in the viewed output; these are separate output streams hence why they appear out of order from a timestamp perspective (think "async"). Obviously, if you're sending stderr and stdout to separate files this quirk will not be apparent; again, it only surfaces when the streams are consolidated.

As a work-around, you could set your Console transport's stderrLevels option to an empty array which tells it to not log anything to stderr, and only to stdout. However, the side-effect to the work-around is that you can no longer distinguish between error and non-error output at the stream level. Be cautious to where you employ this.

For example, when defining the console transport:

new winston.transports.Console({stderrLevels:[]});

IMO, this is not a bug.

[OndroNR]

@zamnuts's answer should be mentioned in readme.