Feature/logger factory

[jf-lavoie]

Hi,

This pull request came from the necessity for me to have a different logger on each http request in express. I need to have a top level id that allows me to correlate requests in a micro service environment.

To do this, I create a child logger on every request in an express middleware. The new child service contains the top level id.

I had to find a way to retrieve the logger and this change request is the solution I propose for my problem. Let me know what you think. Thank you.

Code sample of my use case:

const _ = require('lodash');
const app = require('./app');
const logger = require('./logger');
const addRequestId = require('express-request-id')();
const expresswinston = require('express-winston');

app.use(addRequestId);

app.use((req, res, next) => {
  const childProperties = {
    'X-Request-Id': req.headers['X-Request-Id'] || req.id
  };
  const child = logger.child(_.extend(logger.defaultMeta, childProperties));
  req.logger = child;
  next();
});

app.use(
  expresswinston.logger({
    winstonInstance: (req, res) => {
      return req.logger;
    }
  })
);

It produces winston log entries with the following properties (simplified example from my use case):

{
   "X-Request-Id":"683828f7-54d9-4e07-bd9f-4a2e34b46d32",
   "level":"warn",
   "message":"HTTP GET /projects/5",
   "meta":{},
   "timestamp":"2019-02-04T19:53:52.180Z"
}

[bithavoc]

This looks good, what do you guys think @crellison @rosston ?

[rosston]

I assume there's a specific reason that you need X-Request-Id at the top level, @slam02? To my eyes though, it seems like that sort of info is well-suited to meta (and I've done that in a production app in the past). Creating a logger for each request seems like overkill to me.

That said, winston provides a specific example of a request id when documenting creation of child loggers. So maybe my opinion here is just outdated? 😁

[jf-lavoie]

Hi @rosston ,

Thank you for your comment.

The reason I added the element at the top level is because I do not log the meta for most of my log entries, except at the error levels. It's too noisy for no added values.

I still need to be able to track requests across services with correlation id. Because of the way Winston is designed, I need to create a child logger with the said correlation id to ensure it appears at the top level. Exactly like the link you provided to their documentation.

The problem occurs in the express-winston module. The module will use a single logger for the duration of the application. There is no way to change the logger per request. This is what I try to address with this pull request.

I used the key 'X-Request-Id' trying to be more explicit that it was the id came from the headers. In the end, it is just a name, It could be id, correlation, tracer, requestId...pick what you like. I think debating this name would be beside the point. :)

Thank you.

[rosston]

@slam02 Agreed about the name! I apologize if my comment was unclear. I was only concerned about the creation of a child logger for each request.

It seems like my original opinion is probably not very useful here. I do not see anything that should absolutely block merge. So I will simply abstain from further commentary and leave the decision up to others.

[jf-lavoie]

@slam02 Agreed about the name! I apologize if my comment was unclear. I was only concerned about the creation of a child logger for each request.

I think this as been covered at the source when winston implemented this feature: https://github.com/winstonjs/winston/pull/1471

Also. In my use case, performance is not a critical requirement in the application.

[jf-lavoie]

Hi @rosston, @bithavoc Do you guys have questions on this? Can I help you with anything? Is that pull request accepted?

Thank you.

[jf-lavoie]

Hi @rosston, @bithavoc

Any update on this? Thank you.

[rosston]

I'm okay with this if @bithavoc is, but I don't see myself as the final decision maker on this.

[chiawendt]

I think an simpler solution for your uses case is to add an option to allow dynamically (per-request) adding top-level property.

For example:

app.use(expressionWinston.logger({
  ...things,
  dynamicTopLevelMeta(req, res) {
    return {
      "X-Request-Id": req.headers["X-Request-Id"]
    }
  }
}))

will log

{
   "X-Request-Id":"683828f7-54d9-4e07-bd9f-4a2e34b46d32",
   "level":"info",
   "message":"HTTP GET /projects/5",
   "meta":{},
   "timestamp":"2019-02-04T19:53:52.180Z"
}