Rant about Node.js library logging

rant.md

What I want for library logging

I write Node.js libraries, and I want logging. Why is this so problematic?

Note, I am despairing about how library authors log stuff not how application builders decide on a logging framework.

Hopefully this document can become a spec or feature list for code I will write some day.

The antipattern

I maintain package foo and I depend on log4js. Bob maintains package bar and depends on winston. Charlie maintains package baz and depends on minilog.

My downstream user writes an application which depends on foo, baz, and bar plus npmlog.

This is crazy. The result, in the best case is a tedious application. How can the developer activate debug logging across the board? It's bedlam! In practice Bob, Charlie, and I get many bug reports about something which should be invisible yet ubiquitious, like air.

Features

My half feature list / half whining list:

• I must not depend on some package
  • The whole anti-pattern is too many logging cooks. I am deeply skeptical that another package will help.
  • I want a technique or a custom, not a package. At least not yet.
• I want to document how I work and my user can hook me into their own logger. That's fine for now.
• I want the console.* API
  • .info(), .warn() and .error(). That's fine.
  • This includes util.format() support. I love Winston's structured logs but util.format() is more compatible with the world.
• I want to be silent by default. Principle of least surprise.
• It should be pretty easy for my user to get at my logs.
  • Maybe I emit a "console" event and my user can replace my .info(), .warn(), etc. functions?
  • Maybe I have a .console() function and my user just runs foo.console(console); to get my output on the screen

Non-Goals

Perhaps in the future, but not yet

• Command-line or environment variables to trivially enable/disable my log visibility, severity cut-off, etc.
• The well-known concept of a log "namespace". My user can hook into "networking" logs but ignore "caching" logs.
• Optimized execution in the case where a log message will go nowhere
• Some good solution to the missing console.debug(). From bitter experience, I now insist on being 100% console.* compatible. But there is no debugging level! I will probably just use .trace() and die a little bit inside.
• Be easy to hook into me into logging frameworks (Winston, log4js, npmlog, whatever else)

I think the solution is for libs to emit "log" events, which you can then decide to either print or ignore or send to a db or whatever. I've been planning to eventually make npmlog work this way by default, and only actually print stuff if you set a loglevel on it explicitly.

Then I could easily do something like:

yourModule.on('log', function(level, message) {
  myLogger.log(level, message);
});

where "level" is one of ['error', 'warn', 'info', 'debug'] or something.

Of course, then it's up to all of us in the node logging universe to conform to this API. I'd certainly be happy to accept pull reqs to make npmlog conform to something like this. I'm not too attached to the specifics of the API.

It's worth noting that all the popular loggers seem to have some concept of "levels" which is super handy. It's great to do stuff like log.warn() or log.info() and then at run-time be able to turn the dial up or down.

I'm with @isaacs on this one. Having your objects emit log events works real handy, with then the application allowing filtering of the log levels to display.

For instance in DocPad we use Caterpillar for our logging. We utilise several objects and other libraries that emit log events, and DocPad will bubble those events up the chain to the DocPad object. DocPad is configured to tell its caterpillar instance what log levels to show.

Sidenote, there is actually an RFC which standardizes the log levels - http://www.faqs.org/rfcs/rfc3164.html - we use it for caterpillar. If there is to be a standard format for log events, we should follow that RFC.

Sidenote 2, caterpillar expects log events to be in the format of logLevel?, args... (that being logLevel is optional, and following args are one or many). This format would also have to be standardized to avoid pain.

So the ability to bubble log events up the chain, and tell applications that would normally output log events with a log library to hold off, seems the way to go. However, that doesn't help with avoiding the numerous log libraries being installed in the first place, not sure if that can be fixed... or even if that is a problem...

Thanks, all. Events are okay I guess. I still want a one-line well-known "trick" to come about which becomes idiomatic. There is massive power to tell downstream users:

// See what's going on with foo
foo.logger(console)

Firstly, it's one line of code and it's mnemonic. Also, seriously: I refuse to depend on a log framework anymore. I hate them! I hate them! I hate them! When people invite me to a dinner party I do not insist on bringing my friend Joe, even though Joe is a great guy.

@balupton, thank you very much for your feedback. Your sidenotes are great and I bookmarked the RFC but they aren't directly related to my logging problem. The problem is bloat! The problem is XKCD standards! There is a power vacuum.

That is why I want to tell my users, "Look, I am basically doing console.log(). Do you know console.log()? Great. My console object is all noops by default. You can swap it out out for global.console or whatever else you want. Just stick to the API that Netscape invented in the 90s and we'll be okay."

@isaacs Emitting events is okay, but what if my package does module.exports = function() { /* whatever */ }? I fear each developer will invent their own technique, for no net gain. Some packages export an EventEmitter so they are fine. Others export an object full of functions. Others have a config() or defaults() function (request and nano do this). Some packages are object factories, with each new object emitting its own log events. Maybe I am just despairing too quickly.