6

I am using NestJS v9 with the express adapter and the @nestjs/graphql library and am having issues extracting headers from the graphql request and appending them to the log messages using the pino logging library.

Below is my LoggerModule

import { Module } from '@nestjs/common';
import { ConfigModule, ConfigService } from '@nestjs/config';
import { LoggerModule as PinoLoggerModule } from 'nestjs-pino';

@Module({
  imports: [
    PinoLoggerModule.forRootAsync({
      imports: [ConfigModule.forRoot({ isGlobal: true })],
      useFactory: async (configService: ConfigService) => ({
        isGlobal: true,
        pinoHttp: {
          level: process.env.LOG_LEVEL || 'info',
          redact: configService.get<string[]>('logger.redact.fields'),
          transport: {
            target: 'pino-pretty',
            options: {
              colorize: false,
              singleLine: true,
              levelFirst: false,
              translateTime: "yyyy-mm-dd'T'HH:MM:ss.l'Z'",
              messageFormat: '{req.headers.x-correlation-id} [{context}] {msg}',
              ignore: 'pid,hostname,context,req,res.headers',
              errorLikeObjectKeys: ['err', 'error'],
            },
          },
        },
      }),
      inject: [ConfigService],
    }),
  ],
  controllers: [],
  providers: [],
})
export class LoggerModule {}

As you can see the message format is configured to be:

 messageFormat: '{req.headers.x-correlation-id} [{context}] {msg}',

However, the log message doesn't display the req.headers.x-correlation-id only the context and the msg.

I have tested the configuration with REST requests and the id appears in the logs as expected so it is an issue with GraphQL requests only.

Does anybody know how I can fix this issue ?

Here is a link to a sample github repo with my code

https://github.com/mh377/nestjs-graphql-sample

I have raised an issue with the following libraries

nestjs-pino

https://github.com/iamolegga/nestjs-pino/issues/1342

pino-http

https://github.com/pinojs/pino-http/issues/273

pino-pretty

https://github.com/pinojs/pino-pretty/issues/402

mh377
  • 1,656
  • 5
  • 22
  • 41
  • One thing to note is that context is injected in `Logger = new Logger(AppResolver.name);`. However, it doesn't appear that `req` is in scope when the logger function is called. It's been a while since I've used nestjs but you might check out: https://docs.nestjs.com/fundamentals/injection-scopes#per-request-injection – imaCoden Feb 22 '23 at 18:39
  • 1
    After further investigation I suspect that the problem is in the offiicial nestjs GraphQL module: as far as I can see it is using apollo-server-express for your version, but the logger is not mounted on apollo-server-express, hence the request will never be logged on the express-router level, which is where it should be mounted. – briosheje Feb 24 '23 at 14:08
  • After even further reversing and investigation I think I came up with the real problem: it seems that nestjs-pino creates an `Application Level Logger`, meaning that it actually creates a `Middleware` that is mounted on the Nestjs core engine rather than at the http level. From my understanding, the base apollo driver correctly mounts the express app: https://github.com/nestjs/graphql/blob/fc5e12f618a474f09e31f65d9943a649250b783c/packages/apollo/lib/drivers/apollo-base.driver.ts#L131 but it looks like nest does NOT invoke any further logging information in nest/graphql – briosheje Feb 27 '23 at 09:31
  • To summarize what I said above: it looks like this is neither an apollo issue, neither a logger issue. It looks like (to me) that it actually is the Graphql core engine of NestJS that does NOT invoke the logger and that can be seen by doing a console.trace inside both the controller and the resolver: they take different traces and the first one does get into the logger middleware, while the second one does not. I'm not exactly confident there is a solution for this, another problem might be that the dependency injection does not work as intended but I hope it's not the case. – briosheje Feb 27 '23 at 09:36
  • can you raise an issue on the nestjs github with your findings ? – mh377 Feb 27 '23 at 09:48
  • 1
    I would need to do further investigations to ensure that all what I said is right: most important, I should dig into the source of nestjs understanding how the middlewares are invoked, but yes, if I have enough time to do so in the next days I will open an issue linking to this question as well. – briosheje Feb 27 '23 at 15:18
  • No. Every bug I raised was closed so I decided to implement a workaround where I appended the request Id to every log message – mh377 Apr 14 '23 at 14:47

0 Answers0