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:
winstonjs/winston#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.

[bithavoc]

can you explain a bit more why this change? ExceptionHandler needs the logger instance

[jf-lavoie]

The logger instance is not known at application startup. Which is when this line is executing. The logger instance is known at execution time through the 'getLogger' method.

The only reason why there is an ExceptionHandler is to call getAllInfo on it.

I can think of 2 ways to solve this problem.

1. Build an exception handler on each requests, passing the logger instance. In other works, call these lines (or something similar) on all requests:
   options.exceptionToMeta = options.exceptionToMeta || exceptionHandler.getAllInfo.bind(exceptionHandler);

2. Accept and embrace the fact that ExceptionHandler.getAllInfo does not require the logger instance to build the exception metadata. You can view the implementation here: https://github.com/winstonjs/winston/blob/8423c03c59c31f61f57519b4097420a464c90f83/lib/winston/exception-handler.js#L75

I chose option 2 because it seemed a reasonable tradeoff between readability and a small iterative change.

[jf-lavoie]

@bithavoc

Does that answer your question?

[bithavoc]

@golopot want to throw your two cents here?

[jblevins1991]

Line 119 - 122 seems to provide evidence that this can be called with options.winstonInstance initialized. I don't think it is good for performance to create a new instance every time errorLogger is called for everyone. This seems like a niche feature. I think a better solution would be to leave this as it was and find a good place to remove options.winstonInstance (maybe after winston is finished with a single log?) so that a new instance can be created here, only if you need it. Then we could pass an option to express-winston named uniqueInstances or something of that ilk to trigger this behavior.

[golopot]

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"
}