[BUG] Nestjs-Pino not working correctly with GraphQL requests

[mh377]

• [x] I've read the docs of nestjs-pino
• [x] I've read the docs of pino and pino-http
• [x] I couldn't find the same open issue of nestjs-pino
• [x] This bug is related only to current library or I've tested the same behaviour with the built-in logger and this is not a bug of NestJS.

What is the current behavior?

I am able to append a custom header: x-request-id to each log message for REST requests but not for GraphQL requests.

What is the expected behavior?

I should be able to append a custom header x-request-id to each log message for BOTH REST and GraphQL requests.

Please provide minimal example repo, not code snippet. Without example repo this issue will be closed.

Instructions are in the README.md of the following repo:

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

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

NodeJS version: v16.5.0 OS X https://stackoverflow.com/questions/75446439/nestjs-pino-logger-not-working-correctly-with-graphql-requests

[iamolegga]

Sorry, I don't have time to look at such complex example. In my production environment it works well with x-request-id and graphql. Please take a look at the configuration of pino-http and this comment. Closing

[iamolegga]

Also it could be middlewares order, double check that at the runtime pino middleware goes before module that uses graphql. Debug or simply add console.logs in node_modules/pino-http or node_modules/nestjs-pino

[mh377]

Sorry, I don't have time to look at such complex example. In my production environment it works well with x-request-id and graphql. Please take a look at the configuration of pino-http and this comment. Closing

Do you have an example of a nestjs app that uses x-request-id ?

[iamolegga]

Only private repos, sorry. But we use genReqId see https://github.com/iamolegga/nestjs-pino#faq second question.

genReqId: (req) => req.headers['x-request-id'],

This is example log, mind the req.id field:

{
  "insertId": "oeu4k...e52xm",
  "jsonPayload": {
    "graphql": {
      "operationName": "SomeOperationName",
      "query": "query SomeOperationName { nested query here }"
    },
    "context": "GraphQLLogger",
    "hostname": "...",
    "req": {
      "headers": { ... },
      "method": "POST",
      "params": {
        "0": "graphql"
      },
      "query": {},
      "id": "8ddde5f1e...4498651",
      "url": "/graphql",
      "session": { ... }
      }
    },
    "responseTime": 798,
    "message": "request completed"
  }
}

[mh377]

I have tried genReqId: (req) => req.headers['x-request-id'] but that also doesn't seem to work

@Module({
  imports: [
    PinoLoggerModule.forRootAsync({
      imports: [ConfigModule.forRoot({ isGlobal: true })],
      useFactory: async (configService: ConfigService) => ({
        isGlobal: true,
        pinoHttp: {
          genReqId: (req) => req.headers['x-request-id'],
          level: 'trace',
          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-request-id} [{context}] {msg}',
              ignore: 'pid,hostname,context,req,res.headers',
              errorLikeObjectKeys: ['err', 'error'],
            },
          },
        },
      }),
      inject: [ConfigService],
    }),
  ],
  controllers: [],
  providers: [],
})
export class LoggerModule {}

[naremloa]

I have tried genReqId: (req) => req.headers['x-request-id'] but that also doesn't seem to work

@Module({
  imports: [
    PinoLoggerModule.forRootAsync({
      imports: [ConfigModule.forRoot({ isGlobal: true })],
      useFactory: async (configService: ConfigService) => ({
        isGlobal: true,
        pinoHttp: {
          genReqId: (req) => req.headers['x-request-id'],
          level: 'trace',
          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-request-id} [{context}] {msg}',
              ignore: 'pid,hostname,context,req,res.headers',
              errorLikeObjectKeys: ['err', 'error'],
            },
          },
        },
      }),
      inject: [ConfigService],
    }),
  ],
  controllers: [],
  providers: [],
})
export class LoggerModule {}

You need to generate the id by your self.

// from pino-http README
genReqId: function (req, res) {
  const existingID = req.id ?? req.headers["x-request-id"]
  if (existingID) return existingID
  id = randomUUID()
  res.setHeader('X-Request-Id', id)
  return id
},