How to pass custom data in all lines?

[Skryabind]

I use PassportJS and I want to insert in logs id of logger user. User is stored in req.user object.
How to add req.user.id in any log lines?
I tried to use serializers, but req serializer runs before passportjs, so req.user is not defined at that time.

[mcollina]

After passportJS middleware is run, you can add another middleware creating a new child logger adding the userId:

req.logger = req.logger.child({ userId })

[Skryabind]

@mcollina I tried that, I did a middleware:

app.use((req, res, next) => {
    if (req.user) {
      req.log = req.log.child({user_id: req.user.id});
      req.log.info('Test');
    }
    next();
  });

I get one message with user_id:

{"level":30,
"time":1513615460909,
"msg":"Test",
"pid":72355,
"hostname":"Macintosh.local",
...
"user_id":1}

And another one, generated by ExpressJs, without user_id:

{"level":30,
"time":1513615460992,
"msg":"request completed",
"pid":72355,
"hostname":"Macintosh.local",
...
}

I need to ExpressJs messages be generated with user_id too.

[mcollina]

in which cases is not printing user_id? Maybe req.user  is not defined at all and then the logger does not get set?

[Skryabind]

@mcollina this 2 messages happens in one request.
Lets try another example without using any additional variables:

  app.use((req,res,next)=>{
    req.log = req.log.child({user_id:1});
    req.log.info('Test');
    next();
  });

When I get a request, I get 2 messages, one with user_id and another one without it:

{"level":30,"time":1513655060026,"msg":"Test","pid":99704,"hostname":"Mac-mini-Dmitrij.local","req":{"id":1,"method":"GET","url":"/api/crm/me","headers":{"cookie":"Webstorm-f0d8e326=1b31cfec-fdf3-433c-8fa7-ed2d18de2794; twebank_authmode=Certificate; JSESSIONID=8A356D225BFB30DAD1127C329A0DC27D; connect.sid=s%3A-klLpYSE43ieg3TcVD1f5rAjOJPgWd_5.2zYqXVL1p%2FjBG5DkOv%2Fn0VXXVGicbQ%2FysTk4h%2BoopGc; io=jPg86WSxUeMp5EPVAAAh","accept-language":"ru,en-US;q=0.9,en;q=0.8","accept-encoding":"identity","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36","cache-control":"max-age=0","connection":"close","host":"localhost:3000"},"remoteAddress":"::ffff:127.0.0.1","remotePort":52773},"user_id":1,"v":1}

{"level":30,"time":1513655060111,"msg":"request completed","pid":99704,"hostname":"Mac-mini-Dmitrij.local","req":{"id":1,"method":"GET","url":"/api/crm/me","headers":{"cookie":"Webstorm-f0d8e326=1b31cfec-fdf3-433c-8fa7-ed2d18de2794; twebank_authmode=Certificate; JSESSIONID=8A356D225BFB30DAD1127C329A0DC27D; connect.sid=s%3A-klLpYSE43ieg3TcVD1f5rAjOJPgWd_5.2zYqXVL1p%2FjBG5DkOv%2Fn0VXXVGicbQ%2FysTk4h%2BoopGc; io=jPg86WSxUeMp5EPVAAAh","accept-language":"ru,en-US;q=0.9,en;q=0.8","accept-encoding":"identity","accept":"text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8","upgrade-insecure-requests":"1","user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36","cache-control":"max-age=0","connection":"close","host":"localhost:3000"},"remoteAddress":"::ffff:127.0.0.1","remotePort":52773},"res":{"statusCode":200,"header":"HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nAccess-Control-Allow-Origin: *\r\nAccess-Control-Allow-Headers: Origin, X-Requested-With, Content-Type, Accept, X-CSRF-Token\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 191\r\nETag: W/\"bf-21bdb583\"\r\nVary: Accept-Encoding\r\nDate: Tue, 19 Dec 2017 03:44:20 GMT\r\nConnection: close\r\n\r\n"},"responseTime":87,"v":1}

The second message, 'request completed' is generated automatically by Express and it seems that internally Express use another instance of logger, not req.log.

[mcollina]

My bad: you need to override also the instance in res.log, as that is the one used by that message.

[Skryabind]

Yes, is works:
res.log = req.log = req.log.child({user_id:1});
Thank you!