domino-logger: why we wrote another logger for our node.js app
There are many logging libraries in the npm registry nowadays. Some of them are simple, some are huge packages intended for practically everything. You could notice that many libraries use debug package for verbose logging which is quite nice and simple. Also there’s winston package with lots of transports which supports logging to practically any target: console, file, external services.
So is there any need to write your own logger? The answer is “it depends”. It depends if we need to quickly enable another log storage, if we need to search our logs fast etc. We use domino-logger for our production front-end apps which process hundreds requests per second and right now we’re quite comfortable with it. It’s super simple: it uses debug in development environment and standard streams in production. Why is it so simple?
Logging purposes
But first, I’d like to draw your attention to the purpose of logging in your app. During development you usually want to know practically everything about your app. Sometimes you want to view only output of one component, sometimes you want to see only errors. Second thing is: do you need to store these logs for some time? Usually we don’t need this during development process therefore sending logs straight to stderr/stdout seems to be a simple solution.
Node.js provides util.debugLog for these purposes but there’s much more popular npm module for that called debug. We can set environment variable DEBUG to what we need and run our app showing only our component logs (DEBUG=app:component:* npm start), errors (DEBUG=app:*:error npm start) or practically anything we want.
In production environment logging purposes are different. No one is watching logs regularly because it’s boring. The idea here is: you usually don’t need logs and even error logs, but you need an amount/threshold of the same errors happening daily/hourly/etc especially after releases. These errors are really useful and interesting to watch at. Another thing is: you usually don’t need anything except errors which is the reason logging levels exist. Last but not least: probably you have a need to send logs to different targets: email notifications about errors, everything straight to file log.
In our case we like things being simple: we write all node.js app logs into files, not just errors — everything. Usually we don’t write logs like “here comes request, now we will check something” because this is what comments are used for. Instead our logs are informative and can tell what happened during request processing from the beginning to its end. We also log network requests with timings and unexpected answers body for this. That being said one page load adds about 20–30 lines to log file.
Basically we try to write all our logs into stderr (process.stderr.write under the hood + redirecting stderr to file) because most of information there is for debugging and diagnostic purposes and this is what stderr was designed for (useful links below).
One can say that’s horrible and cannot be fast. Well again: it depends. Our node.js apps process hundreds of requests every second and logging is still not our bottleneck. We can also use some throttling techniques to write logs less often but in our case this would be premature optimization. On the other hand this approach allows us to review every checkpoint of the request processing.
Of course these logs weight much, so we rotate them once a day (logrotate + copytruncate) plus our devops guys synchronize them with separate log storage server. Another problem which is still not resolved yet: grep through 20Gb+ file is not fast. Solution for this could be some kind of map-reduce service like CouchDB, but we still don’t need it yet.
Why not another winston transport
Because we’re not quite enterprise for that. Our production logging is like a winston.transports.Console with custom formatter function. And our development logging is a simple wrapper on top of debug. Should’ve we go so much far?
