Logging

930 views
Skip to first unread message

Mikeal Rogers

unread,
Dec 14, 2011, 2:02:20 AM12/14/11
to nod...@googlegroups.com
I've spent some time rethinking logging.

Logging is strange problem. It needs to be instrumented, to some degree, in all the modules we use, not just in our application code.

For debugging and increased visibility in to production you just want to be notified of the internal workings. 

The traditional log4j approach is kind of ridiculous to instrument as a module developer, you don't really have a need for log levels for instance.

Logging is also one of the very few cases that we need a truly process global module that is not in core.

So, i started to think about what the most minimal API for such a logger might bem.

I created an implementation and a draft spec. The idea here is that we define a minimal logger that different people can implement so long as they obey this minimal API contract. Then in my own modules, like request, I'm going to check for `process.logging` and if it's there I'll get myself a log function and use it accordingly.

I'm open to suggestions about the API but keep in mind that the last of features is it's greatest feature. Anything that can be built on top of this API without any breaking changes should not be in the spec portion.


I'm sure there are typos and misspellings, it's quite late and i'm beat. I'll be using this in request starting tomorrow.

-Mikeal


Axel Kittenberger

unread,
Dec 14, 2011, 2:50:31 AM12/14/11
to nod...@googlegroups.com
I consider using logging categories instead of levels a good idea, but
I don't see why this needs to be global. What you need is an API where
as logging provider you make a message with a log, and as application
you want to give an array of all categories you want to be logged.
They can all write into the same write stream, so let that API from
logging providers been required multiply, no harm.

> --
> Job Board: http://jobs.nodejs.org/
> Posting guidelines:
> https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
> You received this message because you are subscribed to the Google
> Groups "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com
> To unsubscribe from this group, send email to
> nodejs+un...@googlegroups.com
> For more options, visit this group at
> http://groups.google.com/group/nodejs?hl=en?hl=en

Bruno Jouhier

unread,
Dec 14, 2011, 3:08:06 AM12/14/11
to nodejs
Good idea to have a simple global logging function.

A few suggestions:

The API should return null when there is no logging registered for the
module and people should be encouraged to use the following pattern:

var log = require('logging')('mymodulename');

// ...
module.exports = fancy (options) {
log && log('new fancy %method for %url', options)
}


This is better than setting log to function() {} when no logger has
been registered because it avoids useless (and potentially costly)
formatting of messages.

Also, I see a risk of confusion with application level logging /
auditing (which needs severity levels BTW). So I would rather call it
trace/tracing rather than log/logging to make it clear that this is
for traces that the developer will turn on and off during debugging.

Bruno

Bruno Jouhier

unread,
Dec 14, 2011, 3:11:05 AM12/14/11
to nodejs
I agree. The logger is retrieved with a key which is not necessarily a
module name. And a given module may get several loggers with different
keys.

Nuno Job

unread,
Dec 14, 2011, 3:15:27 AM12/14/11
to nod...@googlegroups.com

I would like to be able to run this in the browser too.

Joshua Holbrook

unread,
Dec 14, 2011, 3:42:29 AM12/14/11
to nod...@googlegroups.com
With regards to missing levels, etc,: How about something like,

log( '%message', { message: "Everything is ruined forever", level:
"fatal" });

Assuming the spec ignores extra properties, you could totally use the
object argument to pass metadata. Then, in your globally-accessible
logger, you can handle it however you'd like.

Also, regarding the whole "why does this need to be global" thing: I
think for most 'traditional' logging, it's almost exclusively at the
application level. That could be either because there's no canonical
module/api for easily doing this sort of thing, or because you don't
actually want logging at that level. I'm not sure.

Either way, being able to hook onto this api would be *awesome* if you
wanted said instrumentation.

--Josh

--
Joshua Holbrook
Engineer
Nodejitsu Inc.
jo...@nodejitsu.com

Matt

unread,
Dec 14, 2011, 5:51:56 AM12/14/11
to nod...@googlegroups.com
The key thing that we learned in Haraka is that logging is only useful if you can find the issue that you're looking for (especially relevant on high throughput servers).

So in Haraka every log line tries to get a UUID associated with the current transaction attached to it.

That way if someone gets an 500 error page you can include the current UUID, and if they ask about it you can find the log entries for that UUID.

This has been a HUGE win for large installations.

dodo

unread,
Dec 14, 2011, 8:58:29 AM12/14/11
to nod...@googlegroups.com
i like your event approach on that :)

but i think the same api as for console would be nice, because it's
already documented.
also using the module namespace could make it more readable:

module.log("something happen.")
module.error("fatal!")

also an integration into the current module system could enable the
ability to use logging
in modules without spamming all the time, unless you want it:

require('request').on('logging', console.log)

this is just an idea. because it came to my mind that monitoring
specific modules or
dependencies of specific modules would be easily solvable with this:

require('express/node_modules/connect').on('logging', console.log)

i hope you got the point, because about the syntax i'm not 99% sure
this is wise idea to
introduce an event system for _every_ module, but maybe somebody else
has an option
on that too.

Mikeal Rogers

unread,
Dec 14, 2011, 1:18:36 PM12/14/11
to nod...@googlegroups.com
The reason we check for the a global log rather than a strict import is so that other implementations of this API can be used and the node modules you import will use that implementation rather than the module developer thought of.

That is also why the logger returns a function. A module level function is limited a little more than a returned function might be, this is more extensible.

On severity as a property on context. This is totally doable, the context can take any arbitrary properties you like.

On unique UUIDs. The context is usually an object that is actually being used in code. A logger could easily if (!obj.uuid) obj.uuid = blah. And track that uuid through other log messages. Doing dynamic stuff like this is the main point of just passing the whole context.

This has to be global. When i want to send the messages for my application somewhere, I want ALL the messages. There is not way to insure that a third party module is global for a process, which is why we must use process.logging.

-Mikeal

Mikeal Rogers

unread,
Dec 14, 2011, 2:14:17 PM12/14/11
to nod...@googlegroups.com
FYI, there was already a module named logging, it just didn't show up on search.npmjs, so I renamed.


-Mikeal

On Dec 14, 2011, at December 14, 20115:58 AM, dodo wrote:

Charlie Robbins

unread,
Dec 14, 2011, 10:32:14 PM12/14/11
to nod...@googlegroups.com
Mikeal,

Just an FYI: winston already does all of this: the idea of a global logger is built into it's DNA.

1. The `winston` object (i.e. var winston = require('winston')) is an instance of winston.Logger. So you can just require it whereever you want

var winston = require('winston');
winston.log(level, msg, meta);

2. The `winston` object also has a .get() method which returns a logger for the given namespace:

var winston = require('winston');
var logger = winston.get('somemodulename');

//
// This logger will have all of your levels defined as methods
//
logger.log(level, msg, meta);
logger.info(msg, meta);

I like the idea of string interpolation but it's non-trivial considering the context may contain metadata that should not be interpolated.

So ... yeah. I consider this problem "solved" in my book, but I've been wrong before.

--Charlie

Mikeal Rogers

unread,
Dec 15, 2011, 2:15:47 AM12/15/11
to nod...@googlegroups.com
require('winston') doesn't insure that the module returned is global to the process, which is why I'm advocating process.logging = // preferred logging module.

winston is great, winston has lots features and could easily expose something compatible with this API.

// server.js
var winston = require('winston')
process.logging = winston.logging
winston.enableLotsOfFeatures()
var request = require('request')

I don't expect everyone to use my logger implementation, I only hope that we can agree on an API so that I can tool logs in to request and others can tool their modules and we use whatever logger under the hood that the user prefers in production.

Your problem is only solved for everyone who uses your logger throughout all their modules, I don't think that's going to get us anywhere. People are opinionated about loggers, they'll want to have their own, I just want to agree on the simplest API possible for use in modules so that we can all be compatible.

-Mikeal

Heinrich Göbl

unread,
Dec 15, 2011, 3:07:45 AM12/15/11
to nodejs
I'm quite imposed about winston. Very useful and feature-rich.

{ "tl;dr":
"Don't know whether you want to here stories about the Java ecosystem?
Java runtime in early days didn't provide standardized logging
capabilities.
Then came along Log4J and almost everybody used it. Of course not all,
older frameworks created their own logging. When combining libraries
and frameworks, configuring logging was a nightmare.
It was too late when Java delivered its own standardized logging
(java.util.logging). It missed very valuable features of Log4J and
most projects just don't use it, until today.
Now there is a zoo of logging-bridges, logging facades and logging
libraries. It is very confusing and of course there are a lot of
problems (class-loader, log-formats, transports, ...)."
}

IMHO node.js should provide feature-rich and extensible logging
capabilities, probably as a core module, because logging can become a
real performance bottleneck.

- support for log levels
- support for log categories / modules
- transports / appenders as plug-ins (stdout, stderr, file, syslog,
socket, mail, redis, mongo, ...)
- configurable log formats (date-format, pid, context-info)
- configuration changeable during runtime (w/o restarting -> watchdog)
- check if category/level is logged before calling log-method e.g. if
(log.isDebug()) { log.debug({...})
- support for correlation ids (e.g. UUID) would be plus but could be
handled outside as well

If no standard or de-facto standard is set, we will have that silly
zoo of incompatible loggers like in Java.

Diogo Resende

unread,
Dec 15, 2011, 5:45:01 AM12/15/11
to nod...@googlegroups.com
On Wed, 14 Dec 2011 23:15:47 -0800, Mikeal Rogers wrote:
> I don't expect everyone to use my logger implementation, I only hope
> that we can agree on an API so that I can tool logs in to request and
> others can tool their modules and we use whatever logger under the
> hood that the user prefers in production.

+1

I'm in for the process.log(ging) idea. But for that to work, I would
like to have some common methods there similar to console (warn, error,
..).

---
Diogo R.

vincentcr

unread,
Dec 15, 2011, 12:02:03 PM12/15/11
to nod...@googlegroups.com
>> The traditional log4j approach is kind of ridiculous to instrument as a module developer, you don't really have a need for log levels for instance.

i'm curious as to why you think that? you don't think being able to distinguish between log levels is useful?

Axel Kittenberger

unread,
Dec 15, 2011, 12:50:19 PM12/15/11
to nod...@googlegroups.com
> This has to be global. When i want to send the messages for my application somewhere, I want ALL the messages. There is not way to insure that a third party module is global for a process, which is why we must use process.logging.

Why not enhance console? In my opinion this be'd a more logical place for that.

console.nlog(); or something like that. which has a richer API than
simple console.log, behaves more like util.log and requires for
example a log category and log level. Or enhance util.log and let it
call console.dolog as global backsolution. and console.loglevel and
console.logcats to filter logging.

console.nlog('db', 3, 'message', someobject, 'futhermessage');

Felix Geisendörfer

unread,
Dec 15, 2011, 1:49:28 PM12/15/11
to nod...@googlegroups.com
My approach (as inspired by http://www.12factor.net/):

* stdout / stderr are the *only* methods used for logging (via console, or the process streams)
* library code *never* actively logs, it emits passive 'log' events that I may hook up to console.log / console.error

That's it. If you are doing one of the following, then IMO you're doing it wrong:

* Writing logs to disk/network from within your program (Unix has pipes, use them!)
* Treating your logs like structured data (they are not)
* Choosing what to log at program runtime (you can filter this with grep, seriously)
* Adding timestamps to your log within your program (again, should be done from the outside)

--fg

Alex Pilon

unread,
Dec 15, 2011, 1:59:26 PM12/15/11
to nod...@googlegroups.com
Does choosing what to log.. do you include being able to tell the program what to log? ie warnings vs debug vs fatal errors only?

Arnout Kazemier

unread,
Dec 15, 2011, 1:59:51 PM12/15/11
to nod...@googlegroups.com
Got to disagree with the timestamps, I want to known exactly when a certain issue occurred in case of race conditions, not when it's finally written out to to a log. As logging is mostly done in an async fashion. There can be a different in time between the events that occurred.
--

hel...@gmail.com

unread,
Dec 15, 2011, 2:01:13 PM12/15/11
to nod...@googlegroups.com
Node is single threaded. This isn't an issue.
Sent from my BlackBerry device on the Rogers Wireless Network

From: Arnout Kazemier <in...@3rd-eden.com>
Date: Thu, 15 Dec 2011 19:59:51 +0100
Subject: Re: [nodejs] Re: Logging

Felix Geisendörfer

unread,
Dec 15, 2011, 2:08:22 PM12/15/11
to nod...@googlegroups.com
Node does take care of the ordering. However, stderr is blocking, stdout is not. Those may not be in order in regards to each other.


Mikeal Rogers

unread,
Dec 15, 2011, 2:11:52 PM12/15/11
to nod...@googlegroups.com
On log levels:

In your application code levels make sense. You do some operations you'd rather not do and you take what are actually errors, log them, and try to move on without failing.

modules do not do this. an API i expose for generic consumption has two modes, it works or it fails and i give an error or success condition.

what a module wants to log is entirely informational, it's up to the consumer of that log to decide whether or not an error is expected or not and log that accordingly.

in other words, modules should not be logging information they give back to the consumer of that API already, they only need to log the steps it took to get to that condition that are opaque to the consumer.

levels are totally contextual. for instance.

A CouchDB library might think that a GET that returns a 404 is an "error", it would seem like the right assumption to make. But to the consumer it's not, the consumer of the API was checking to see if the document was there and if it was they wanted the current revision, when getting this 404 they will simply write a new document. A log that sent an error message would give the wrong impression entirley.

On Dec 15, 2011, at December 15, 20119:02 AM, vincentcr wrote:

>> The traditional log4j approach is kind of ridiculous to instrument as a module developer, you don't really have a need for log levels for instance.

i'm curious as to why you think that? you don't think being able to distinguish between log levels is useful?

Mikeal Rogers

unread,
Dec 15, 2011, 2:15:33 PM12/15/11
to nod...@googlegroups.com
On Dec 15, 2011, at December 15, 201110:49 AM, Felix Geisendörfer wrote:

My approach (as inspired by http://www.12factor.net/):

* stdout / stderr are the *only* methods used for logging (via console, or the process streams)
* library code *never* actively logs, it emits passive 'log' events that I may hook up to console.log / console.error

I thought about this. The problem of course is that some APIs are purely functional so the only thing they can do is expose a global emitter just for logs which lack context :(

I found that a better method was actually to make the logger purely functional and pass in a context to each call, this allowed for much more dynamic handling of log messages across both evented and functional libraries.


That's it. If you are doing one of the following, then IMO you're doing it wrong:

* Writing logs to disk/network from within your program (Unix has pipes, use them!)
* Treating your logs like structured data (they are not)

When debugging those hard to reach bugs, and you lack dtrace, you appreciate log messages have a context that you can hook in to dynamically. Especially once you have too many log messages to actually read them all usefully.

* Choosing what to log at program runtime (you can filter this with grep, seriously)
* Adding timestamps to your log within your program (again, should be done from the outside)

Agreed, thats why it's not in.


--fg

Shripad K

unread,
Dec 15, 2011, 2:15:44 PM12/15/11
to nod...@googlegroups.com
@Mikeal: +1. Never thought of it that way. It could be made worse if the same CouchDB library used a blocking console.error for a 404.

Mikeal Rogers

unread,
Dec 15, 2011, 2:16:43 PM12/15/11
to nod...@googlegroups.com
In my API it is not guaranteed but if you want a timestamp you only have to add it to context at the time was created.

Since this is node even if you're a few microseconds off it doesn't matter because nothing else can happen in the process between log() call and when the event fires that I can add a timestamp to the context.

Felix Geisendörfer

unread,
Dec 15, 2011, 3:09:33 PM12/15/11
to nod...@googlegroups.com
I thought about this. The problem of course is that some APIs are purely functional so the only thing they can do is expose a global emitter just for logs which lack context :( 
I found that a better method was actually to make the logger purely functional and pass in a context to each call, this allowed for much more dynamic handling of log messages across both evented and functional libraries.

Since your logger assume adjustments to the libraries using it anyway, how about improving the libraries in question to expose their services as composable interfaces instead? This allows the user of such libraries to inject logging at any point through inversion of control.

--fg
 

vincentcr

unread,
Dec 15, 2011, 3:35:56 PM12/15/11
to nod...@googlegroups.com
i understand what you mean, but even as a module implementer, wouldn't you want to be able, or at least have the ability, to let the user know the difference between "this you will almost never care about", "this may be of interest to you", and "this is a problem"?

i would suggest that your 404 example falls into the "expected error" category, like returning null, and that logging anything in that case would be a design mistake.

but as a user, you might still want to tune the verbosity level of the logs you are looking at, so that you can filter out things that you don't need to know. i'm thinking especially of 'debug-level' logging that only the maintainer would normally care about.

Mikeal Rogers

unread,
Dec 15, 2011, 3:55:23 PM12/15/11
to nod...@googlegroups.com
think about what you're saying. 

you're saying that different users have different needs for filtration, which is true. but the context for that filtration is never understood by the module developer, it's only understood by the user, so what purpose does handing levels *to the module developer* serve?

the user needs to tune the verbosity level, but the module developer has no idea what messages relate to what level, only the user does. which is why you leave it to the user, with some help from logger implementations, to filter the right messages. the module developer cannot, and should not, be put in the position to assume a particular level about anything that might happen.

hel...@gmail.com

unread,
Dec 15, 2011, 4:00:20 PM12/15/11
to nod...@googlegroups.com
I really respectfully disagree. Module authors know what are deeper and deeper levels of debug information and have historically dealt with that just fine. Personally I tend to think of it as how deep in the call stack you are. Some things deeper down are 99% of the time just Not worth logging. Plus remember that more logging has a cpu and disk space impact.

Sent from my BlackBerry device on the Rogers Wireless Network

From: Mikeal Rogers <mikeal...@gmail.com>
Date: Thu, 15 Dec 2011 12:55:23 -0800
Subject: Re: [nodejs] Re: Logging


Mikeal Rogers

unread,
Dec 15, 2011, 4:03:03 PM12/15/11
to nod...@googlegroups.com
I don't think we'll get much traction with module developers by insisting that they change the structure of their code to match a different pattern we think is more correct.

People like to write things the way they write things. Our job as module developers is to expose APIs that are small enough that they fit well inside of any crazy programming style.

The purpose of this logging spec is to create a contract *anyone* can follow in any style and log messages that are compatible with different logger implementations, which may or may appeal to your aesthetic. 

Injecting an opinion about "composable interfaces" in to the spec is not necessary and insures it will rarely be used.

Mikeal Rogers

unread,
Dec 15, 2011, 4:05:26 PM12/15/11
to nod...@googlegroups.com
calling a function does not have a disc impact and the CPU impact, in v8, isn't something to be concerned with.

CPU and disc impact are subject to filtration rules which can be imposed by the user.

if you look at the code for logref I don't even do string interpolation unless someone is listening for an event so that I don't waste CPU cycles.

hel...@gmail.com

unread,
Dec 15, 2011, 4:09:02 PM12/15/11
to nod...@googlegroups.com
The disk and cpu impact was in response to whoever said log everything and let the user grep it out instead.
Sent from my BlackBerry device on the Rogers Wireless Network

From: Mikeal Rogers <mikeal...@gmail.com>
Date: Thu, 15 Dec 2011 13:05:26 -0800

Felix Geisendörfer

unread,
Dec 15, 2011, 4:15:20 PM12/15/11
to nod...@googlegroups.com
Injecting an opinion about "composable interfaces" in to the spec is not necessary and insures it will rarely be used.

That's why I'm not providing a spec or contract for people to follow. I'm stating what kind of software I like to write / use.

--fg

Andi

unread,
Dec 16, 2011, 4:24:32 PM12/16/11
to nod...@googlegroups.com
I don't agree. Logs are objects and not strings. I want to search in my log collection: Give me log document of type x in the last 24 hours, grouped by y, ordered by z. Aren't log files outdated? I want to get meaning out of what I log and parts of the analysis can reappear in the application. This was the point about 12 factor that I did not agree on.

Andi

unread,
Dec 16, 2011, 4:32:14 PM12/16/11
to nod...@googlegroups.com
To conclude with my semantics:
- data
  an array of arguments the log function is called with. Not a string
- transport
  WritableStream, database, ..., includes a reduce function that serializes the data into an appropriate format, depends on the format. A WritableStream will just concatenate the data, in an object oriented database, all objects are merged into one document, etc.
- traits
  which make up logging levels, you can prefix any logger with new semantics, like time, memory usage, whatever you like, and there are default traits for node specific objects like HTTP request, etc.

I believe that logging libraries must be focussed much more on semantics. I have an alpha version of a library that implements my concept. It is inspired by winston but it cleans up a lot of the API clutter. If you are interested I can put it on github.

Mikeal Rogers

unread,
Dec 16, 2011, 5:06:47 PM12/16/11
to nod...@googlegroups.com
What I'm focusing on is *only* the portion of the API used by module developers that want to log messages.

Most of this is implemented outside of that API so I'm wondering what modifications, if any, you are advocating.

Andi

unread,
Dec 16, 2011, 5:25:47 PM12/16/11
to nodejs
I get a 404 when trying to access the page.

On Dec 16, 11:06 pm, Mikeal Rogers <mikeal.rog...@gmail.com> wrote:
> What I'm focusing on is *only* the portion of the API used by module developers that want to log messages.

Exactly, and I think my idea is closely related to yours, and it's an
alternative and better view on logging. A logger function has the
properties transports and traits (both arrays), and you can just
change them and so change the behavior of the logger.

Code example: https://gist.github.com/1488297

Mikeal Rogers

unread,
Dec 16, 2011, 5:58:35 PM12/16/11
to nod...@googlegroups.com

Joshua Holbrook

unread,
Dec 16, 2011, 6:06:39 PM12/16/11