Improved generic logging functionality in core

[Thomas Fritz]

Hi, i have created an issue on Github with a basic idea of how such
logging functionality could look like:
https://github.com/joyent/node/issues/2581
I want to discuss it, so please write your comments.

My first question is. Is it possible to get the filename and line
number of the logging call from within the log.debug call for
instance?

Kind regards

---

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

[Eldar Djafarov]

Well. There are modules for this. I do not think this needs to be a part of nodejs core.

[Arnout Kazemier]

I'm already doing this with my own logging module devnull:

https://github.com/observing/devnull

--

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

[Thomas Fritz]

Well that is true. But every userland module does it in a different
way. So if you have dependencies to lets say 5 or more userland
modules (express, socket.io, ...) which each using different logging
mechanisms with different formats you can not normalize them in a way
YOU would like to use in YOUR application. So logging output is
somehow useless. Not completly but...
With a generic "core" module such userland logging framework would
still exist and needed for different logging "backends" like file,
database, snmp, etc. BUT they would built upon this core module which
allows you to configure format, etc and extend it with a userland
logging framework afterwards like you want to.

In case of express or socket.io or other libraries, if they would just
use this core logging then, it would be easy for you to configure
logging format and "plug" a userland logging framework to it which
writes all logs to a file for instance.
Without the need to reafactor anything.

---

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

2012/1/20 Eldar Djafarov <djk...@gmail.com>:

> Well. There are modules for this. I do not think this needs to be a part of
> nodejs core.
>

[Thomas Fritz]

Exactly!! Looks great. Easy and powerful.

But in my opinion something like that has to be in the core. Because,
even when devnull is great and i would definately use it, other will
not. So if node.js would have such a generic core logging framework, i
think other userland logging frameworks like devnull with multiple
transports will then be built on top of that core, which will then
allow the end application to define and configure its logging
behaviour like he wants it to be.

In fact the API of devnull is mostly exactly like thought of. But for
the generic core logging i would not support multiple transports or
multiple configuration envs as this i would see in userland modules
built on top of that.

I think that this is really important for better debugging and error
research. Especially when node apps beeing more and more in production
log monitoring and alerting gets more and more important. Without a
unified log format this is not that easy as it sounds as one would
maybe think.

---

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

2012/1/20 Arnout Kazemier <in...@3rd-eden.com>:

[Diogo Resende]

On Fri, 20 Jan 2012 11:28:41 +0100, Thomas Fritz wrote:
> Hi, i have created an issue on Github with a basic idea of how such
> logging functionality could look like:
> https://github.com/joyent/node/issues/2581
> I want to discuss it, so please write your comments.
>
> My first question is. Is it possible to get the filename and line
> number of the logging call from within the log.debug call for
> instance?

This is useless, you're just defining yet another logging framework.
All
the options you set (useColors, *format) should not be there. To be
used
by any module you should have something like:

var log = require("logger")("my_module_id"); // or app_id or whatever
log.info("whatever");
// and perhaps..
log.info("whatever", aditionalStuffObject);

Date should be added automatically, format and colors should be global.

var log = require("logger");
log.setDateFormat("d-m-Y ...").useColors(true);

---
Diogo R.

[Thomas Fritz]

I am fine with such an API too, as long as you can override existing
configurations globally, to have the possibility to configure
'dateFormat' and 'useColors' for all active loggers.

So for instance if express would use 'setDataFormat('Y-m-y
H:i:s').useColors(true)' and my app depends on express i want to have
the possibility to override all existing log settings. Otherwise it
makes no sense to me.

With "my_module_id" or "app_id" you mean a free identifier used in the
log output, right?
so the above log messages would output something like this, right?

[20-01-2012 13:03] [INFO] [my_module_id] [/path/to/file.js:12] "whatever"

I have not found a way to get the line number and the file where the
logging happened. Is there a clean way to get this information?
Another question is how to configure or handle log levels which should
be logged or not logged?

---

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

2012/1/20 Diogo Resende <dres...@thinkdigital.pt>:

[phidelta]

Hi all,

I actually think this should never be in core. I also happen to think
that modules should not do logging AT ALL.

Logging is a feature of an application not of a module. If a module
has something it deems important enough to log, then let it emit an
event. If I as the app developer agree, then I will log it in the
fashion of my choice.

When I evaluate whether or not to use a module, any module that logs
stuff or writes to the console (unless of course that is its stated
purpose) is automatically disqualified. Even a framework like Express
should never log anything. What it should do is have the app emit an
event. If I as the developer then decide I want that event in a log,
then that is my decision.

So logging is not something that should be anywhere, much less in
core.

Regards, Phil

P.S.: At the same time all my apps do extensive logging using devnull,
but it's my App that triggers the actual logging.

[Ruben Tan]

I second this. It is really hard to manage logs right now that I have no control over the verbosity of the modules I use (there are hacks of course) and logging should be up to the discretion of the Dev, not the module. This way we won't need to use an external logger to push to while ignoring potentially important logs thrown by modules just because there are too much unimportant noise generated in total.

phidelta <philipp...@gmail.com> wrote:

[Thomas Fritz]

I fully agree with you. But the reality looks different. Look at the
most depending modules on NPM (express, socket.io, request, optimist,
connect, etc.). No single module of that does neither emit log events,
nor do they use the same format for "logging" or emitting logs, or
error.

So with that reality in mind we have to face reality that this will
never happen, when node does not provide a simple generic
infrastructure for this. Maybe there is no need for a extra "logging"
core module. Perhaps just a documented
debug,log,notice,info,warn,error event is enough. So everyone could
just use the global console object as everyone does already and this
will emit a event on console.

For instance:
console.on('log', function(file, line, message) {
});
console.on('error', function(file, line, message) {
});

and library modules like the one mentioned above would just use
somethin like, i do not know, maybe:
console.emit('log', "this is the log message")
// or
console.emit("error", "this is an error");

But i fully agree that this has nothing to do in the core. It is the
responsibilty of the final app using this modules to decide what to
log and what not. But we are not in this situation, so apparently
something has to be done here.

---

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

2012/1/20 phidelta <philipp...@gmail.com>:

[Diogo Resende]

On Fri, 20 Jan 2012 04:18:53 -0800 (PST), phidelta wrote:
> Hi all,
>
> I actually think this should never be in core. I also happen to think
> that modules should not do logging AT ALL.
>
> Logging is a feature of an application not of a module. If a module
> has something it deems important enough to log, then let it emit an
> event. If I as the app developer agree, then I will log it in the
> fashion of my choice.

What you consider a module I can consider a dependency and find myself
building an app *with modules*. In an extreme view, any file is a
module.

> When I evaluate whether or not to use a module, any module that logs
> stuff or writes to the console (unless of course that is its stated
> purpose) is automatically disqualified. Even a framework like Express
> should never log anything. What it should do is have the app emit an
> event. If I as the developer then decide I want that event in a log,
> then that is my decision.
>
> So logging is not something that should be anywhere, much less in
> core.

What I exposed can and is probably better on the module land, not core.
The only thing I don't know how to, is get the file/line of the caller.

---
Diogo R.

[jmar777]

Quick description of what we're currently doing:

- Dump everything to stdout (a la 12factor.net).
- Structure our log messages (we use JSON to describe generic
"events", which logs are a specific type of)
- Use an external aggregator to collect the log data (we're using
Flume)
- Make that aggregator (again, a Flume agent in our case) to filter
based on our designated format

Pros: works pretty good, scales well, reusable across technologies
other than node
Cons: we could conceivably miss valuable log data from third-party
modules (although that can be fixed through agent configuration), has
(marginally) more overhead than using something like winston to
publish straight to the desired transport

Two cents on the original topic: I don't think that the core logging
facilities should be evolved into anything resolving a framework, but
I do think there are at least two possible "light" enhancements that
would increase it's utility:

1) Provide an optional (but "standard") way to designate which module
is the source of a log message (similar to what Diogo referenced
above). This would allow higher level logging utilities to provide
black/white-list filtering/inclusion of log messages based on the
source module.
2) Provide a supported approach of overriding (or at least reacting
to) the default `console` behavior (e.g., make console an
EventEmitter, or allow alternate behavior to be specified via function
passing).

> 2012/1/20 phidelta <philipp.dun...@gmail.com>:

[jmar777]

sp/resolving a framework/resembling a framework/

[Douglas Martin]

Here is another logging module that supports what you requested.

http://pollenware.github.com/comb/symbols/comb.logging.Logger.html

http://pollenware.github.com/comb/symbols/comb.logging.PropertyConfigurator.html

This module also supports a multitude of appenders(RollingFile, FileAppender, JsonAppender, and ConsoleAppender), custom levels, formatting, and a fuller logger inheritance. 

[tjholowaychuk]

Express doesn't output logs, if you're talking about logger() you can
pass it any format you wish. I think it would be interesting to have
something like visionmedia/debug in core, then like you say we would
have a unified debugging mechanism, no need to go do a different thing
per-module. plus it's like 5 lines and already used in core (just not
as a util). Logging is a bit more opinionated so im not sure about
that

On Jan 20, 7:57 am, Douglas Martin <jrpercuss...@gmail.com> wrote:
> Here is another logging module that supports what you requested.
>

> http://pollenware.github.com/comb/symbols/comb.logging.Logger.htmlhttp://pollenware.github.com/comb/symbols/comb.logging.PropertyConfig...
>
> This module also supports a multitude of appenders(RollingFile<http://pollenware.github.com/comb/symbols/comb.logging.appenders.Roll...>,
> FileAppender<http://pollenware.github.com/comb/symbols/comb.logging.appenders.File...>,
> JsonAppender<http://pollenware.github.com/comb/symbols/comb.logging.appenders.JSON...>,
> and ConsoleAppender<http://pollenware.github.com/comb/symbols/comb.logging.appenders.Cons...>),

[Mark Hahn]

 I consider logging a feature of my application and I prefer to have full control over my logging.  I would never use anything built into the core. 

[Dobes]

I think what will/should happen is that people will eventually agree
to converge on the same logging library. What might be a good idea is
to coordinate a push for the adoption of the same logging library by
the most popular modules and it is likely that use of the library will
spread from there. Building it into the core isn't a very good idea,
since the core modules don't change or evolve as quickly as a library
can and the process for choosing the API that would be used to create
the core module may not be as democratic as simply seeing what library
people are using the most (sort of a free market approach I suppose).

In Java it is often extremely useful to be able to selectively enable
logging for certain parts of libraries and have it spew out all sorts
of debug information to help trace something that is going wrong. In
programming with javascript we can "enable" logging for certain events
by just editing the source code for the library, though, so this isn't
as big of a deal as in Java. As the platform matures I think you'll
find people building remote management consoles (ala JMX) allowing you
to enable/disable logging/tracing of certain events at runtime without
having to modify the sources. This is a useful debugging capability
that libraries can and should participate in when the time comes.

Reading about the work being done with dtrace for monitoring I think
that's a useful approach - rather than have the libraries expose
events via a bunch of logging statements there could be a standard way
to expose certain events that can be accessed via a dtrace client or
simply logged to a file with a bit of filtering.

[Thomas Fritz]

For your interest. I tried to build a module based on the ideas i
proposed in here. https://github.com/thomasfr/node-konsole

konsole's API is identical to the internal console API. So usage of
konsole is exactly like console. The difference is that konsole will
not write to stdout or stderr. Instead it will emit a 'data' event and
one event named after the log level.
For example:

konsole.info("foo");

will emit a 'data' event and a 'info' event.

On the GitHub Page there is some more info how to use it, or how it is
intended to use.

Kind regards

---

Thomas FRITZ

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

2012/1/21 Dobes <dob...@gmail.com>:

[Jeff Barczewski]

Thomas,

This looks nice, I was wanting something like this.

Would you consider making the module/line number optional? (so I could turn this off)

Reason I offer this idea is that it would be nice to be able to use this in place of console (and to be able to leave it in the code). When in production you could simply not listen to the events. When you want to debug/monitor, start listening.

However I am not real comfortable leaving calls to konsole in place it if will be calculating module/line number by creating and parsing stack trace. It feels like this would be quite a bit of overhead on each and every call, even if I don't need it or worse even if I am not even listening to any konsole events.

If you made this optional, I could decide whether I want to have this information and keep the overhead to a minimum.

Let me know what you think.

Jeff

[Thomas Fritz]

2012/1/26 Jeff Barczewski <jeff.ba...@gmail.com>:

> Thomas,
>
> This looks nice, I was wanting something like this.

Thanks. I also was looking for something like that. I actually
proposed that there needs something to be done in the core, so that
developers of modules are using logging the right way and not in very
different ways.

Could you open an issue?
You are right. In production you normally do not want to do that kind
of logging. I think i will have to reorder the callback arguments
then.
I will try add a configuration for this.

>
> Jeff

[Thomas Fritz]

For your interest:

I fixed your issue.
It is now possible to configure if a stack should be generated.

In the new version the usage changed a bit, now i think i am happy
with the result.

* konsole overrides the default console functions. So in a module
where you have used console.* functions you just have to add a
require("konsole")(); at least to override consoles functions.
* But you could also return a konsole object without overriding - just
call var konsole = require("konsole")("any label"); As before konsoles
API is identical to consoles one. So you can easily change it.
* You will also get the pid from where the log came from and the
process type (worker or master) - useful if you have different workers
of the same file running
* you also get a time diff in milliseconds since the last log with the
same label (you can turn this off the same way you can turn tracing
off)
* It is also now mandatory to add at least one listener otherwise,
nothing will ever be written to stdout.

I have added one more example, the cluster example from the node.js
docs and updated the example before.

Take a look at the readme to see what it can do for you:
https://github.com/thomasfr/node-konsole

I am thinking of adding some ENV Variable checking directly in
konsole. There is an issue opened, please comment if you want that and
how you want that feature to be.
Another open issue is, but i am not sure yet, if i should ANSI color
utility functions, so one could easily colorize its ouput in his
callback. What do you think?

Kind regards

---

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

2012/1/27 Thomas Fritz <frit...@gmail.com>: