[BUG] logger.assign does not add properties to "request completed" log.

[vladiulianbogdan]

[x] I've read the docs of nestjs-pino

[x] I've read the docs of pino

[x] I couldn't find the same open issue of nestjs-pino

What is the current behavior?

When I call this.logger.assign({ someKey: someValue }), the key is properly added to the logs that belong to a request except the one that marks the end of the request "Request completed".

What is the expected behavior?

I would expect that the method this.logger.assign({ someKey: someValue }) adds the key and value to all the logs belonging to that request.

Please mention other relevant information such as Node.js version and Operating System.

I am using nestjs-pino 2.2.0.

[iamolegga]

I'm not sure that this is a bug, maybe just a limitation of the underlying library? Can we add extra fields on runtime to "Request completed" log with pino-http?

[iamolegga]

@vladiulianbogdan can you check desired behaviour on pino-http in minimal repo example? Or should I close this issue?

[bonejon]

Hi @iamolegga, I'm also interested in this behaviour. Looking at the pino-http repository this should be possible OOTB, however it does seem to be related to the ordering of the middlewares.

I found this thread (https://github.com/pinojs/pino-http/issues/30) which seems to describe the exact behaviour mentioned by @vladiulianbogdan. I will try and make a repro, but I think pino-http is running early in the order of middleware and serialising the request before any logger.assign({...}) is run.

[iamolegga]

Just checked such example:

const express = require('express');
const pinoHttp = require('pino-http');

const app = express();

app.use(pinoHttp({ prettyPrint: true }));

app.get('/', (req, res) => {
  req.log = req.log.child({ foo: 'bar' });
  res.send('foo bar');
});

app.listen(8080);

and this doesn't work.

All the suggested here dirty hacks cannot be used because it's not universal for library with many users or add unnecessary complexity to configuration. Will check if we can solve this with AsyncLocalStorage, but in case if it's not possible I'll add this to the docs as a limitation of the underlying library.

[iamolegga]

Unfortunately, after spending a whole day on this I could not find a solution. I believe this feature should be made on pino-http first without adding any workarounds. Will add this limitation to docs

[jamper91a]

I have the same problem and I could not find a solution, but this is a way to show some values on requests completed. I need the user role and id to be shown on the logs, but they do not show on complete request, so what I did was to modify customProps from pino htpp to add those values. In my case those values are from the jwt token, here is my configuration

LoggerModule.forRootAsync({
      imports: [
        JwtModule.registerAsync({
          imports: [ConfigModule],
          useFactory: (configService: ConfigService) => ({
            secret: configService.get<string>('jwt.secret'),
          }),
          inject: [ConfigService],
        }),
      ],
      inject: [JwtService],
      useFactory: async (jwtService: JwtService) => {
        return {
          pinoHttp: {
            level: process.env.NODE_ENV === 'production' ? 'info' : 'debug',
            transport: {
              target: 'pino-pretty',
              options: {
                singleLine: true,
                colorize: true,
                levelFirst: true,
                translateTime: "yyyy-mm-dd'T'HH:MM:ss.l'Z'",
                messageFormat:
                  '[{role}:{userId}] [{req.headers.host}{req.url}][{context}] {msg} [{responseTime} ms][{res.statusCode}]',
                ignore: 'pid,hostname,context,res,req,responseTime',
              },
            },
            autoLogging: true,
            customProps: function (req, res) {
              const bearerToken = req.headers.authorization;
              if (bearerToken) {
                try {
                  const token = bearerToken.replace('Bearer ', '');
                  const user: UserTokenDto = jwtService.verify(token);
                  return {
                    role: Role[user.role],
                    userId: user.id,
                  };
                } catch (e) {
                  return {
                    role: 'ANON',
                    userId: '0',
                  };
                }
              } else {
                return {
                  role: 'ANON',
                  userId: '0',
                };
              }
            },
          },
        };
      },
    }),

As you can see on my message format I need the role and userId (which I assign using a JwtGuard). To be able to show those values on requests completed I send the customProps function which take the bearerToken and validate that token using JwtService (https://docs.nestjs.com/security/authentication#jwt-functionality).

I hope this will help anyone

[hasokeric]

You are my hero.

[MarcusBondezan]

This is a way to solve the problem. But unfortunately if we are using a guard to verify the authentication, we are making this twice for every request. I wonder if pino-http will introduce this feature to solve our problem in a better way.

[johaven]

If you use nestjs/passport, you can handle this like this :

import { AuthGuard } from '@nestjs/passport'

@Injectable()
export class AuthAccessGuard extends AuthGuard('authAccess') {
  ...
  handleRequest<TUser = any>(err: any, user: any, info: any, context: ExecutionContext, status?: any): TUser {
    const request = this.getRequest(context)
    request.raw.user = user ? user.login : 'anonymous'
    return super.handleRequest(err, user, info, context, status)
  }
  canActivate(context: ExecutionContext) {...}

// Pinolog options
customProps: (req, res) => ({
    user: req.user
})