Logging

[Mikeal Rogers]

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.

https://github.com/mikeal/logging

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]

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]

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]

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]

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

[Joshua Holbrook]

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]

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]

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]

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]

FYI, there was already a module named logging, it just didn't show up on search.npmjs, so I renamed.

https://github.com/mikeal/logref

-Mikeal

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

[Charlie Robbins]

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]

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]

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]

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]

>> 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]

> 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]

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]

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]

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]

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>

Sender: nod...@googlegroups.com

Date: Thu, 15 Dec 2011 19:59:51 +0100

To: <nod...@googlegroups.com>

ReplyTo: nod...@googlegroups.com

Subject: Re: [nodejs] Re: Logging

[Felix Geisendörfer]

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]

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]

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]

@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]

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]

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]

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]

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]

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>

Sender: nod...@googlegroups.com

Date: Thu, 15 Dec 2011 12:55:23 -0800

To: <nod...@googlegroups.com>

ReplyTo: nod...@googlegroups.com

Subject: Re: [nodejs] Re: Logging

[Mikeal Rogers]

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]

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]

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>

Sender: nod...@googlegroups.com

Date: Thu, 15 Dec 2011 13:05:26 -0800

[Felix Geisendörfer]

> 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]

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]

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]

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]

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]

it's been relocated.

https://github.com/mikeal/logref

[Joshua Holbrook]

> I get a 404 when trying to access the page.

Possibly because it moved? https://github.com/mikeal/logref

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

How about some api examples? Maybe I'm just being lazy, but I really
don't want to have to decipher a coffeescript implementation to know
how to use the api in javascript.

As a module developer, I have *no* idea who or what is going to be
consuming my logging messages. All I know is that there may or may not
be a "process.logging" defined, which hopefully takes predictable
arguments. I can accept a type signature of (text, obj) because it
should be able to cover multiple styles of logging (text-based or
object-based) without exploding.

Obviously, we all have varying opinions of the "right" way to log
messages (logref, winston, text vs. objects, the role of metadata and
log levels or lack thereof, appropriate log storage backends, etc),
but this is precisely why the "process.logging" api should be simple
and predictable (to allow for use by multiple opinionated logging
mechanisms)!

As I said earlier, I think the second argument should be used to pass
metadata (such as log level) if desired, such that the process.logging
implementation can take or leave properties that aren't interpolated
into the string.

(Speaking of: A separate interpolation library to use with the
"%thing" substitution would be handy for implementing process.logging
imo.)

--Josh

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

[Diogo Resende]

On Fri, 16 Dec 2011 14:25:47 -0800 (PST), Andi wrote:
> 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.

Your idea has nothing to do with Mikeal's. Let's face it, you just read
the
mails in fast forward and didn't get the point. Mikeal is pointing in a
standard
way of *ACCESSING* logging tools. Your talking about what to log
(context, not text).

I think that is important too, but that should be the second part. You
should both
just do a freaking module and publish here so people can start to use
and love :)

I'm +1:

- process.log(context[, context, .. ])
- process.log.info(text)
- process.log.warn(text)
- process.log.whatever(text)

---
Diogo R.

[Charlie Robbins]

I'm with Felix on this one. Rather than have some blessed global logging implementation, modules can emit events which you can choose to log or not in your application. It would of-course be useful for modules to have "debug" modes where these events are logged for you, but that is left to the module author. 

In application-level code I'm almost exclusively using EventEmitter2 (https://github.com/hij1nx/eventemitter2) now so this is achieved through the catch all listener or namespaced `log **` events. It's also how we do logging in Flatiron (https://github.com/flatiron/broadway/blob/master/lib/broadway/plugins/log.js#L60-91)

Cheers,

Charlie

--
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+unsubscribe@googlegroups.com

[Mikeal Rogers]

this thread is just talking in circles now. the entire purpose of this thread is to avoid a "blessed global logging implementation". but whatever, i'm done talking.

this week i'll be adding logging to request, i'll use the spec at https://github.com/mikeal/logref , if you want to observe log messages in request your logger will need to implement a compatible function that the user can set on process.logging. the same for my other modules when I get around to them.

i've tried to open this up and not just go with my own thing but nobody seems to share the same concerns and people are more interested in forcing adoption of their own loggers or module patterns. we get stuck in this pattern a lot where discussions run in circles as people push the discussion back to a conclusion they've already written, at least we didn't get in to flow control or fibers on this one ;)

-Mikeal

nodejs+un...@googlegroups.com

[Joshua Holbrook]

I for one think all logging should involve flow control with fibers
because calling functions is far too difficult.

> the entire purpose of this thread is to avoid a "blessed global logging implementation"

I think your proposal handles this well in terms of what's passed to
the function (a string and object covers most bases), but you're still
suggesting a global method on process and I can understand why that
would upset people. We've all been trained to approach global
variables with the attitude of, "there has to be a better way," and I
don't not thoroughly convinced that logging is an exception.

> Rather than have some blessed global logging implementation, modules can emit events which you can choose to log or not in your application

This could work!

module.emit('log', "%thing is %verb", { thing: "Josh", verb: "awesome!" });

module.on('log', process.logging);

Not that you'd need a global .logging anymore, but the point is that
you can expose logging over an event emitter instead of calling a
global function this way, and that's kinda cool.

I do think this thread brought out a lot of discussion on what the
"right way" to do logs (and about how all others are obviously wrong),
but I also think there's been some good advice and discussion here.
Just because we disagree doesn't mean we're talking in circles...yet.

--Josh

--

[Mikeal Rogers]

On Dec 20, 2011, at December 20, 201112:45 PM, Joshua Holbrook wrote:

> I for one think all logging should involve flow control with fibers
> because calling functions is far too difficult.
>
>> the entire purpose of this thread is to avoid a "blessed global logging implementation"
>
> I think your proposal handles this well in terms of what's passed to
> the function (a string and object covers most bases), but you're still
> suggesting a global method on process and I can understand why that
> would upset people. We've all been trained to approach global
> variables with the attitude of, "there has to be a better way," and I
> don't not thoroughly convinced that logging is an exception.
>
>> Rather than have some blessed global logging implementation, modules can emit events which you can choose to log or not in your application
>
> This could work!
>
> module.emit('log', "%thing is %verb", { thing: "Josh", verb: "awesome!" });
>
> module.on('log', process.logging);
>
> Not that you'd need a global .logging anymore, but the point is that
> you can expose logging over an event emitter instead of calling a
> global function this way, and that's kinda cool.
>
> I do think this thread brought out a lot of discussion on what the
> "right way" to do logs (and about how all others are obviously wrong),
> but I also think there's been some good advice and discussion here.
> Just because we disagree doesn't mean we're talking in circles...yet.

My answer to both your comments is the same answer.

A user running a service in production wants to attach a truly global handler for logging. As much as we like to think that require('module') returns something global, it doesn't. That's why the user needs to attach a function to process, which is truly global, before importing any other modules.

For instance, let's say that I add log events to the watch module.

I do require('watch').on('log', logger.handler('watch'))

Then I import a module that uses watch, like node-couchapp. But node-couchapp bundled that dependency, or it required a different version. And it doesn't add logging. Now I'm screwed as the person running the service, i can't get logging events out of watch where it counts.

Yes, I did think about this problem before I wrote this spec. I've been one of the biggest advocates against *anything* global in node and treating modules as global in any context. It turns out, for module developers, that is almost always true, but for people developing applications and services, they need to add global hooks in to their application for debugging. If you look at the current debugging tools available (node-inspector, dtrace) they all hook in globally in to node, we need the same for logging.

[Joshua Holbrook]

> But node-couchapp bundled that dependency, or it required a different version. And it doesn't add logging.

It seems like the "right thing" for node-couchapp to do would be to
forward the events up the chain, something like:

watch.on('log', myModule.emit.bind(myModule, 'log') );

The problem I can foresee with this approach is that you can't always
trust module authors to forward the logs in any meaningful way. Then
again, can you also trust them to not define their own
process.logging? I think we could, but I've had discussions in
meatspace with people that disagree. Given Murphy's Law, someone will
eventually mess this up, so I suppose the real chore is finding a way
that minimizes opportunities to screw up. Perhaps process.logging has
a lower chance of screw-up than re-emitting log events. Who knows? I
sure don't.

> Yes, I did think about this problem before I wrote this spec.

I believe you, but that doesn't mean you aren't going to be fighting
an uphill battle. ;) Fwiw, I think process.logging is at least a good
enough idea to try out regardless of these implementation details.

> this week i'll be adding logging to request

Cool! I'd definitely be interested in seeing how it works out in practice.

--Josh

[Mikeal Rogers]

On Dec 20, 2011, at December 20, 20111:58 PM, Joshua Holbrook wrote:

>> But node-couchapp bundled that dependency, or it required a different version. And it doesn't add logging.
>
> It seems like the "right thing" for node-couchapp to do would be to
> forward the events up the chain, something like:
>
> watch.on('log', myModule.emit.bind(myModule, 'log') );
>
> The problem I can foresee with this approach is that you can't always
> trust module authors to forward the logs in any meaningful way. Then
> again, can you also trust them to not define their own
> process.logging? I think we could, but I've had discussions in
> meatspace with people that disagree. Given Murphy's Law, someone will
> eventually mess this up, so I suppose the real chore is finding a way
> that minimizes opportunities to screw up. Perhaps process.logging has
> a lower chance of screw-up than re-emitting log events. Who knows? I
> sure don't.

If someone overwrites a global in their module they should be shot. We can enforce this as a community.

There are lots of cases where foolish or malicious overwriting will break stuff in node, we don't really have an enforcement mechanism other than convention and community.

[Jan Schütze]

Hello,

thank your very much for this interesting discussion - nice read :-).

Like you said some lines earlier, logging and what to log depends
pretty much on the user reading the log.

# process.logging vs console.log

I fully agree, that logging is a global thing. This would be the case
with Felix's approach on using the stdout+stderr for log output, same
for process.logging and so on. Why not use console.log and replace it
with your implementation?

What's the full difference in using (from your example):

if (process.logging) var log = process.logging('mymodule')
log("what i want to log");

to:

console.logPrefix = 'mymodule';
console.log("what i want to log");

I actually would go so far, that console.log for each module could be
implemented in such way, that it's already logging with a logPrefix
which reflects the module name.

Resulting in a simple:

console.log("what i want to log");

Overriding the Logger would be something like:

console = require("my-own-logging-implementation");

at the top of your run_server.js/run_console.js script.

# Log Levels

I understand your 404-example from couchdb. This is a valid point.
Though when you are debugging a case with couchdb and a reverseproxy
in front, you may want to log anywhere if the 404 is retrieved by
couchdb or the reverseproxy. Thus having the option to turn at least
verbosity level to ON would be great. It's completely difficult to
explain the difference between debug, trace and info to somebody who
is new to this stuff. Thus having only error (something is wrong:
stderr), log (something to log: stdout, so to say) and some kind of
verbose logging (turned on on request in case of debugging or
maintaining the module).

Have fun coding,
Jan

--

  http://dracoblue.net

[Charlie Robbins]

I'm not against a global logging solution, but I'm not really comfortable with some global object having hooks into stdout and stderr. 

Why not have process.logging just be an event emitter which consumers can choose to subscribe to or not?

--Charlie

[Thomas Fritz]

May be a little bit offtopic and i hope i am not bringing another
aspect to this discussion, but what is really annoying in node.js
modules is that everyone uses another logging mechanism and another
log format . Even worse, some uses tabs, some uses spaces at the
beginning and many are using Bash colors(!!!!). OK, they are pretty
and better to read but it is a mess when dealing with multiple
different ouputs - they are getting useless.
I am OK with stdout and stderr for logging purpose, but i think there
has to be a better generic way of writing those logs to stdout and
stderr, because otherwise everyones doing it different in the end. In
my opinion this should be in the core of node (perhaps on top of
console.log) but very generic and should be extensible so it is room
for third party logging frameworks. But at the generic level it will
use stdout and stderr. debug, info, notice,warn go to stdout, error to
stderr.

For instance:
var logger = require("logger");
logger.error(String message, Error error) // logger.error("this is an
error message") would output something like this (maybe with bash
color codes surrounding the message ;) ) [2011-12-23 13:37] [ERROR]
"This is an error message"
logger.warn(String message)
logger.notice(String message)
logger.info(String message)
logger.debug(String message)

Maybe the date format logging format and other options like using bash
colors should be configurable (Where?).

Just my 2 cents

What do you think?

Kind regards

---

Thomas FRITZ
web http://fritzthomas.com
twitter http://twitter.com/thomasf

2011/12/23 Charlie Robbins <charlie...@gmail.com>:

[Axel Kittenberger]

While logically its IMHO a desirable solution it means a lot of
overhead when nobody is interested in all these messages.

[Thomas Fritz]

Addition:

logger should be an EventEmitter so you can hook into log events like
"error", "warn", "notice", "info", "debug"
And the logging output should contain the log source (module name or
file path) and the line number additional to the date and log level.

Kind regards

---

Thomas FRITZ
web http://fritzthomas.com
twitter http://twitter.com/thomasf

2011/12/23 Thomas Fritz <frit...@gmail.com>: