Middleware logging... how to?

[soggie]

Hi guys, I'm looking at koa-i18n and it uses debug as a means to log information. I think this is sub-optimal and makes it hard for koa users to control what kind of information gets printed.

My suggestion is to provide an info and debug method alongside throw in ctx so that there is a standard way for middlewares to bubble up messages and as an end-user of koa.js you can choose your own logging library to handle the logs.

What do you guys think?

[hallas]

I think I don't understand your argument. What is sub optimal about it?

The context doesn't really know anything about which middleware is processing it at this moment anyway.

Our current approach lets you log any way you want, which is super optimal :)

[tj]

debug isn't really designed for long-lived logging, it's meant to be a solution for libs that would otherwise not have any logging, just transient development debugging etc.

However I do agree some standardization would be nice, logging is an epic mess if everything is different, but people have a hard tim even agreeing on levels and methods of logging (json vs text etc) so it would be tricky to get into core I think

[soggie]

My argument is this: in the ideal world, logging should be the end user's impetus entirely. This is important when you start to write log parsers which dumps your logs into aggregator engines. The more uniform your logs are, the better. And to ensure that your logs are pretty, you need to have some form of control over what module gets to output stuff.

To be honest I haven't have a clue yet. Haven't done any deep thinking into how to accomplish this, but I'll come up with a code sample later tonight to illustrate what I feel would be an improvement over the middleware system in koa.

[tj]

Agreed, I've switch back and forth myself, that's why I'm not sure I would commit to either structured or unstructured. I have mixed feelings about both, especially with Go, structured logging is nottttt fun

[soggie]

// on the middleware side... (called mid)

module.exports = function mid(app, opts) {
  return function *(next) {
    this.log({ foo : 'bar' });                    // we will call this log_1
    this.log('info', 'this is an info message');  // we will call this log_2

    yield *next;
  }
}

// on the app side...

var app = koa();

mid(app);

app.on('log', function (payload) {
  // here I get to do my own logging
  // 
  // the output for log_1 payload is:
  //
  // [ { foo : 'bar' } ]
  //
  // the output for log_2 payload is:
  //
  // [ 'info', 'this is an info message' ]
});

In this case, we've provided the method for middleware to bubble up their logs to the end user without polluting STDOUT or STDERR. It is then the user's impetus to determine how best to parse the payload... either through simple console.log, or have the community adopt a simple format like

// for info:
{ message : 'this is the log message', level : 'info' }

// for error:
{ message : 'this is an error message', level : 'error', err : <err object> }

or something similar. I figure that would at least provide a way for middleware to submit information back to koa without having them to resort back to using and choosing their own logging methods.

Let me know if this proposal sounds silly in the grand scheme of things.

[hallas]

That might not be a bad idea. I like that we would have a standard log function that would handle all cases. I do not like multiple fns such as this.log, this.warn etc.

Also I got confused because you said bubble, I assume all you're talking about here would be emitting a log event?

[soggie]

@hallas well... I'm not sure what the right term is. But yeah, most likely an emitted event. And I'm on the same page as you... I have no love for this.log, this.warn, this.trace, this.debug etc. Just one "channel" for us to receive all kinds of feedback or info from middlewares and let the user decide what to do with it.

[soggie]

This is actually a pretty easy piece of code in application.js:

app.log = function() {
    this.emit('log', Array.prototype.slice.call(arguments));
};

[hallas]

You might want to make sure that the ctx is passed into the log event, so you can log stuff about the context as well :D

[soggie]

Just a sidenote... I notice this issue is kind of similar to #219

[yanickrochon]

I personally would not consider a logger to be a middleware, but a context property. Also, it is a standard to have 'debug', info, warn, error, etc. Something like

app.use(function * () {
  this.logger.log(level, message, data);
  this.logger.info(message, data);
  this.logger.warn(message, data);
});

However, since not so many people agree with the latter, the helper functions could simply be created dynamically (through a setup process).

var context = require('koa/lib/context');

context.logger.warn = function(message, data) {
  context.logger.log('warn', message, data);
};

I like the event-based concept, though on the logger property instead for consistency, and to separate responsibility.

app.logger.on('log', function (evt) {
   // evt.level = string, log level
   // evt.message = string
   // evt.data = any
   // evt.context = object, application context
   // evt.timestamp = unix time (int)
});

[ruimarinho]

@soggie thank you for bringing this up. I'm actually going over this issue at the moment and while I'm an advocate of the debug module for its simplicity, I concur it would be awesome to have a standard way - sanctioned by the koa community - in order for custom loggers to be passed down through all middlewares and also including koa's own context, request and response objects.

I like the event-based concept, but won't it introduce too many performance hurdles with high load? Correct me if I'm wrong, but I think this could be kept really simple, e.g.:

application.js

var debug = require('debug')('koa:application');

app.log = debug;

context.js (shorthand used by middleware)

this.log = this.app.log;

Then we'd just need to pass our own function:

var log = require('bunyan');

var app = koa();
app.log = log.debug;

mid(app);
app.listen();

What do you think?

[tj]

My main worry is the structured-vs-unstructured log approaches since they're completely different. The pros probably out-weigh the cons there though, that would help mitigate the need for tracing middleware too. Any other maintainers have thoughts on this? @koajs/owners

[jonathanong]

i think all public middleware should cohere to some strict standard (i.e. only strings). each logger can support additional features like objects, arrays, etc, but those types of logs should only be used by the app, not public modules.

but i'm not sure what that strict standard is...

[yanickrochon]

@ruimarinho the problem with app.log = whatever is that, when using middlewares such as koa-mount, and/or under certain cases, you might lose that reference. This is why I suggested attaching to koa/lib/context instead.

[tj]

Yeah that's where I'm torn too, choosing between structured and unstructured is tricky. Let's keep it on the back burner for now for post-1.0

[hallas]

I'm leaning towards providing a suite of log methods like warn, info, log, debug and having them emit a log event on the application which comes with the log record and the context. That way people can listen on the event and log it the way they need to.

[cmwelsh]

+1 with a default log configuration to write logs to stderr. Koa should be the central dispach for middleware logs and even console output if we want to foster an ecosystem.

[fengmk2]

Summary above, there're two ways for logging:

• log event

app.on('log', function (log) {
   // log.level = string, log level
   // log.message = string
   // log.ctx = ctx
});

• logger instance
  • methods: debug(), info(), warn(), error()
  • app.logger
  • ctx.logger, alias to app.logger

[wenshiqi0]

I prefer event,not the instance.Make a chance to write logger on my own,and feel much more fun.Actually I still think to make a middle ware for package the request ,response and ctx. = = Why not

[tj]

I'd vote for structured if this is something that people want to see in the core. printf-style is too hard to work with in practice, basically useless for querying so I wouldn't want to promote that out of the box. Just regular old log.warn({ stuff here }) – which could arguably be done in module-land without Koa's involvement at all (just a convention).

[yanickrochon]

I agree with @tj. The middleware would allow, just like koa-view, to use logging adapters more easily (such as winston, etc.), and would not tie this functionality to the core.

What I don't like about events is the unnecessary steps :

1. user calls app.log (or app.emit('log', ...))
2. koa forwards to the even listeners (thus make koa responsible for such listeners)
3. listener receive events and user-custom call their logger
4. logger dispatch message

However, with a middleware, we get rid of steps 2 and 3 altogether :

1. user calls app.logger.log or this.logger.log, however the middleware is implemented.
2. logger dispatch message

Thus, completely separate logger from core and even allow users to implement their own middlewares.

[aheckmann]

The more I think about this, the less I believe we should build anything into core. It requires heavy-handed standardization of things many have differing opinions of - while also requiring keeping it flexible enough to be completely overridden to support things people are already doing (e.g. this).

I'm +1 for documenting and promoting what a lot of the community seems to already be doing vs prescribing something for everyone. I see two common things in koa apps and modules regarding logs:

1. 3rd party module logging - Debug: Via documentation on the website, we can recommend its use in all 3rd party modules. It's flexible and easily toggled on/off. Lots of modules already use it (non-scientific method, real numbers would be good).
2. Application logging - Custom: At the application level, have no default logger. Leave this undefined in koa itself and let each app make its own decision. If they want to use debug, they can. Bunyan? Go for it. We could add a logging patterns section to the website for the popular loggers out there and be done with it.

If ^ doesn't fly here, then I'm +0 for creating a standard ctx.{debug,info,warn,error,fatal}() method and documenting the method signatures. If the method arguments are documented, then anyone can easily override them with their own custom loggers. By default, the methods could do something like this. However, we would probably need to go further and standardize on a way to differentiate between 3rd party middleware and application level logging to make it really useful.

[niieani]

How about, instead of worrying about standardizing issues when creating ctx.{debug,info,warn,error,fatal}(), we instead opt to make ctx.log into a Proxy object. Here's how it could work:

app.log = new Proxy({}, {
  get: (target, name) => function() { 
    app.emit('log', [name, ctx, ...arguments]) 
  }
});

Then you could to:

ctx.log.error('your params...');
ctx.log.whatever('param1', 2, 3, 4);
ctx.log.crazy('works');

And it would pass the name of the function as the first parameter in the event. No problem with standardization of logging levels, since people can use what they want and it looks better than passing the level as a parameter.

Better yet, with this the community could create pluggable interfaces to any other loggers and they'd just listen for the right events and invoke their own methods.

The downside is that for now Proxy still requires --harmony_proxies flag passed to Node, but that will probably change relatively soon. We could wait until that happens before implementing this.

[niftylettuce]

@nicoder I like this approach.

[jonathanong]

it doesn't seem we've come to a conclusion, so i'm going to delegate this to "userland". if you're interested in profiling middleware, follow this discussion: #219

• we have the https://github.com/orgs/koajs/teams/logging/repositories team. if you are interested in contributing, let me know.
• we have some options: https://github.com/koajs/trace https://github.com/koajs/timer https://github.com/koajs/statsd if you are interested in maintaining any of these, let us know here https://github.com/koajs/koa/issues/638
• if you have a tracing module that you think is suited for the @koajs/logging team, please let us know here: https://github.com/koajs/koa/issues/638