Logging req.user properties

[scott-martin]

I would really like to log some properties off of req.user which is added in middleware that is after pino-http. It looks like pino-http serializes the req object immediately because it creates a child logger with the request object. Would it be possible to postpone serialization of req until the request finishes? Or possibly add another hook that could be used to serialize once the request is finished? Could anyone offer a suggestion of how I could accomplish what I'm trying to do here?

[davidmarkclements]

Yep totally possible -

You need to do two things

1. place the logging middleware beneath the middleware that adds req.user
2. pass a custom req serializer

const pino = require('pino')()
const pinoMiddleware = require('pino-http') // or require('express-pino-logger') or require('koa-pino-logger) - whatever it is you're using, concepts are the same

app.use(middlewareWhichAddsUserToReq)

app.use(pinoMiddleware({
  serializers: {
    req: function customReqSerializer (req) {
      return {
        id: req.id,
        method: req.method,
        url: req.url,
        user: req.user,
        headers: req.headers,
        remoteAddress: req.connection.remoteAddress,
        remotePort: req.connection.remotePort
      }
   }
 }
})

Closing for now, but let me know if that works for you

[scott-martin]

Would this still log the request if the authentication middleware threw an unauthorized exception? Also, another issue with this is that I'm pretty certain it would make the responseTime be a little less accurate because it would leave out any middleware processing that already happened.

[scott-martin]

Yeah I just verified that it does not in fact log the request if the authentication middleware fails. Here is a workaround that I was able to do to get it working.

const pino = require('pino')();
const pinoMiddleware = require('pino-http');

app.use(pinoMiddleware()); // ensures we capture all requests
app.use(authenticationMiddleware); // adds `req.user`
app.use((req, res, next) => {
   if (req.user) {
        req.log = res.log = req.log.child({ 
            user: req.user
        });
    }
    next();
}); // redefine the res.log object as a new child logger that includes the user object

This works because in line 32 of logger.js you can see that pino-http is using the logger object that is defined on res to perform the final log.

[davidmarkclements]

hmm that does mean you're creating a child of a child logger, although the perf hit is still probably negligible. Another way is to use a getter:

app.use(pinoMiddleware({
  serializers: {
    req: function customReqSerializer (req) {
      return {
        id: req.id,
        method: req.method,
        url: req.url,
        get user () { return req.user },
        headers: req.headers,
        remoteAddress: req.connection.remoteAddress,
        remotePort: req.connection.remotePort
      }
   }
})) 
app.use(authenticationMiddleware)

If you need Node < 4 use Object.definieProperty instead

The only issue to perf here may be the closure reference, so do benchmark it

[scott-martin]

That's clever. I'll give it a shot. Thanks for the help!

[davidmarkclements]

let me know if it works

[gswalden]

Thanks for the tips above! Here's a very concise way to maintain usage of the default serializer with an additional user property.

const pinoHttp = require('pino-http');
const logger = pinoHttp({
  serializers: {
    req: reqSerializer
  }
});

function reqSerializer(req) {
  return Object.assign(
    pinoHttp.stdSerializers.req(req),
    { user: req.user }
  );
}

[davidmarkclements]

@gswalden

It is indeed more concise, but it wont be anywhere near as fast. Object.assign vs returning a new will be much slower. I would recommend against that approach

[joakimbeng]

If someone (like me) finds this the "getter solution" from above does not work, because I think the req object is serialized at an earlier stage than when req.user (or req.raw.user) is available.
So the solution is instead to add a getter to the res serialization like this:

app.use(pinoMiddleware({
  serializers: {
    res: function customResSerializer (res) {
      return {
        statusCode: res.statusCode,
        header: res.header,
        get user () { return res.raw.req.user }
      }
   }
})) 
app.use(authenticationMiddleware)

[kyrisu]

The "getter solution" does not work because req is already serialized when passed to the custom serializer. We need to use the raw request (req.raw):

app.use(pinoMiddleware({
  serializers: {
    req: function customReqSerializer (req) {
      return {
        id: req.id,
        method: req.method,
        url: req.url,
        get user () { return req.raw.user },
        headers: req.headers,
        remoteAddress: req.remoteAddress,
        remotePort: req.remotePort
      }
   }
})) 
app.use(authenticationMiddleware)

This also applies to the connection property which is already mapped to remoteAddress and remotePort keys.

[twelve17]

@joakimbeng

I think the req object is serialized at an earlier stage than when req.user (or req.raw.user) is available.

Thanks, this solution worked for me. But it seems indicative of a problem with pino-http. I'm not 100% sure of this, but it seems the reason this works is that the autologger uses this to get access to the res, which in turn has access to the req available to the middleware issuing the log request, as opposed to the request serializer, which seems to use a req available at the point in the middleware chain that pino-http is added at.

@davidmarkclements does my observation sound correct to you?

I just began adopting this library, and, perhaps wrongly, had assumed that the request and response serializers would receive req and res with state at the time of logging. But this statement makes me think my assumption was wrong:

place the logging middleware beneath the middleware that adds req.user

So perhaps using res.req is a workaround in that assumption.

[kohtala]

This works because in line 32 of logger.js you can see that pino-http is using the logger object that is defined on res to perform the final log.

This is no longer true since 8.3.0. customProps can help, but you need the child logger on res.log anyway if you use it.