Broken logs
TL;DR: Node.js fails developers with the complete absence of logging frameworks and primitives to support it.
Disclaimer: This isn’t a Node.js bashing post, I use Node.js for my day job and I find it quite expressive and productive. I have no complaints for the open source community trying to build node.js and move it forward. But I’m very frustrated that we are in Node.js 11 and there’s no progress on this to be seen.
Logging
Logging is an essential part in developing and delivering software. We log to announce we are trying to start the app or when we’ve done starting and are ready to accept connections. We log when we try to connect to a resource. We log errors and api responses. We might log warnings about problematic conditions or state. We might even use logging to report certain metrics (Not the best of practices, but I’ve seen it done quite a lot).
But what is actually defined as “logging”? Let me first define what logging isn’t: Logging isn’t “printing to stdout” printf/fprint/echo/console.log()/print()/println are all not logging. While they allow me to output text to stdout, they are limited to text (mostly) and stdout, and do not allow the control and precision real logging systems allow. What is logging? Logging is a way to output text (mostly) messages in a controlled format allowing me to answer 4 questions: What happened? When did that happen? Where did that happen? What is the importance of what happened?.
An essential part of logging is the ability to separate control configuration from actual logging statement. We might sprinkle logging messages (with various logging “levels”) through our program, but we need the ability to control what class of log would go where. Logging configuration controls usually has “appenders” (python has handlers) which define the way to process log messages. It would have filters, controlling what gets logged, and a concept of logging levels. For example a logging configuration would allow me to log from INFO level and above to stdout. And in the case of an ERROR level log, send to both stdout and a dedicated error aggregation service (Think rollbar or sentry) . While defining that for http requests for a sensitive service I’ll also log to a rotating log file, except for messages from a specific user which would be filtered out. A decent logging configuration would allow me to change the sentry error logging level to INFO or add another filter on what I log, without touching the actual application data.
Logging systems and good logging systems
While real logging systems (compared to console.log) always have a notion of a timestamp, good logging solutions (in python for example) can also automagically add the “where” part: what file/module? What function? What line?.
Good logging solutions would automagically take take care of context like exception stack trace (like logger.exception in python does). Good logging solutions would also defer log message evaluation to the actual logging output step, no need to do text formatting if the minimum LOG LEVEL is higher than the logged message. This might be a big performance hit for large enough apps.
Good logging solutions have a built in concept of log namespacing, together with a built in filtering. This is a powerful tool allowing me to turn on/off specific parts of the logging of an app or an installed lib without touching the rest.
Logging as an integration point
Logging is also an integration point. Lots of central error/exception reporting tools integrate through a specific logging handler/appender. It’s a no brainer — If I log an exception or an error, I report it to the error aggregation service in the same line of code. But there’s a catch. This is possible only if standardized logging primitives are available in the programming language, if those exist, The error aggregation provider can build their appender/handler logging integration and know that this solution would probably work on 99% of python apps. But if there isn’t a standardized logging solution or at least a commonly adopted one, vendors need to maintain lots of different node.js client libraries or just move this burden to the developer (which in turn might just ignore this integration, because it demands extra work and there’s never time, and no one tasked you to do this).
The state of Node.js logging
While I hope we are past the days of “logging” with console.log and console.error (We are past those days right?) the state of node.js logging is still broken.
Logging functions are missing from the stdlib and I don’t know of any plan in the foreseeable future to add them. The same goes for still missing language features needed to implement more a useful logging solution: like getting the module name and line number “automagically” to the logger. So we don’t seem any closer to a stdlib solution.
And while I would really prefer a stdlib solution, there also doesn’t seem to be a commonly adopted “standardized” solution. The fragmented, partly maintained, open source solutions, are really not a good solution for the problem.
BUT! (Common replies I get)
- “We don’t want a bloated stdlib!” — Another library in the stdlib doesn’t really matter in the backend, where node.js processes live. Besides, my latest node.js service with only 24 direct dependencies (2 of them are connected to logging, 9 for linting and testing) has a sprawling node_modules with 1404 folders and subfolders! I wonder how many of them are logging related, but surely, node modules bloat is not a real concern in the community.
- “It won’t conform with frontend js in the browser” — While Emcascript committees do take the browser as a major target, Node.js does already have libs (think fs for example) that have no place in the browser. That’s cool, it’s a different runtime.
- “We already got winston. Just use winston”(Replace winston with bunyan/log4js or your prefered logging solution) — See above. While Some of those libs are nice and not utterly broken, they still suffer from the lack of logging primitives allowing them to be a full logging solution. And even if you did configure winston to do all your app logging correctly you’ll be out of luck with your installed npm modules. Winston can’t help you with that.
- “We can just change the prototype to do whatever we want” — Oh well, even if everyone used console.log (which they don’t) this still doesn’t look like a great idea, changing the behavior of a built-in function. I’m quite sure that every linter would start screaming “red alert, red alert” if I did that.
So what can we do now?
Currently I’ve moved to use log4js in my projects which is a nice solution (within the existing constraints). It has a concept of appenders and levels (and the ability to control different levels for appenders with a dedicated appender which behaves like a filter: “logLevelFilter”).
Log4js also has a companion log4js-api library which I use in installable npm modules. Log4js-api allows my lb to use a logger, but it won’t do anything unless the app using the library has log4js installed and appenders configured. Some open source library expose logging as configuration with environment variables or object/file config. Other libs allow me to pass a logger function while initializing and use it. Those two solutions are far from perfect, but better then the vast majority of npm libraries I’ve encountered which just ignore this and log/console print whatever and however they want.
A way forward?
Maybe the way forward can work around the steering committees? Maybe logging libs can adapt the idea of a logging stub (like log4js-api) with a common api for logging and configuring, which any logging app can connect to and configure? Maybe we can at least standardize the different configuration options, so all logging libs can read a common logging configuration? I sure hope so, but I’m afraid the fragmented landscape of js libs won’t help us to get there. I believe that part of node.js growing up should include adding logging as part of the platform.
