[BUG]

[guy-frontegg]

trafficstars

• [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?

Hello I've been trying to replace our logger in NestJs to Pino using Nestjs-pino.

Tested it on the example project and it's working but our production project it's not working. We are using NestJs 9 with Fastify Am I missing something?

LoggerModule.forRoot( {
			pinoHttp: {
				level: 'info',
				genReqId: (req, res) => {
					return 'temp';
				},

			},
			useExisting: null, <------------------ //this was tested with null or true
			exclude: ['/health', '/metrics']
		}),

This is the output

{
    "level": 30,
    "time": 1677161037660,
    "pid": 89908,
    "hostname": "GuyL-Mac-8.local",
    "req": {
        "id": "req-1", <--------------------------
        "method": "GET",
        "url": "/resources/configurations/v1/public",
        "query": {},
        "headers": {
            "host": "localhost:3016",
            "connection": "keep-alive",
            "cache-control": "max-age=0",
            "sec-ch-ua": "\"Chromium\";v=\"110\", \"Not A(Brand\";v=\"24\", \"Google Chrome\";v=\"110\"",
            "sec-ch-ua-mobile": "?0",
            "sec-ch-ua-platform": "\"macOS\"",
            "upgrade-insecure-requests": "1",
            "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/110.0.0.0 Safari/537.36",
            "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7",
            "sec-fetch-site": "none",
            "sec-fetch-mode": "navigate",
            "sec-fetch-user": "?1",
            "sec-fetch-dest": "document",
            "accept-encoding": "gzip, deflate, br",
            "accept-language": "en-US,en;q=0.9,he;q=0.8"
        },
        "remoteAddress": "127.0.0.1",
        "remotePort": 65317
    },
    "res": {
        "statusCode": 403,
        "headers": {
            "content-security-policy": "default-src 'self';base-uri 'self';block-all-mixed-content;font-src 'self' https: data:;form-action 'self';frame-ancestors 'self';img-src 'self' data:;object-src 'none';script-src 'self';script-src-attr 'none';style-src 'self' https: 'unsafe-inline';upgrade-insecure-requests",
            "cross-origin-embedder-policy": "require-corp",
            "cross-origin-opener-policy": "same-origin",
            "cross-origin-resource-policy": "same-origin",
            "x-dns-prefetch-control": "off",
            "expect-ct": "max-age=0",
            "x-frame-options": "SAMEORIGIN",
            "strict-transport-security": "max-age=15552000; includeSubDomains",
            "x-download-options": "noopen",
            "x-content-type-options": "nosniff",
            "origin-agent-cluster": "?1",
            "x-permitted-cross-domain-policies": "none",
            "referrer-policy": "no-referrer",
            "x-xss-protection": "0",
            "content-type": "application/json; charset=utf-8",
            "content-length": "13"
        }
    },
    "responseTime": 15,
    "msg": "request completed"
}

What is the expected behavior? I expect to see requestId as 'temp'

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

1. We are using Node 18 with Alpine/ MacOs / windows -> basically we tested it on all platforms.
2. We are using NestJS-9 and all npm packages are up to date.

[iamolegga]

If you create a bug issue you have to provide minimal example repo with the bug. Unfortunately I'm unable to to guess what's misconfigured in your particular case. 90% of issues is modules order (pino should go first). Also useExisting should be just skipped if you provide configuration for pino via this module and not using existing fastify's logger

[guy-frontegg]

I am sorry, it was on our private repo. I will try to create a repo with valid example. Regaring the useExisting we tried all just to verify this was not the issue. I already asked the Pino and the Pino-http guys and they said it's not an issue with their library.

[guy-frontegg]

Hi @iamolegga , I've forked your wonderful repo and changed the example to use Fastify as you requested. https://github.com/guy-frontegg/nestjs-pino/tree/nestify-test I changed the genReqId as follows

@Module({
  imports: [
    LoggerModule.forRoot({ pinoHttp: {
            level: process.env.LOG_LEVEL,
            quietReqLogger: true,
            genReqId: (req) => {
                return 'hello';
            }
        }
    })
  ],
  controllers: [AppController],
  providers: [MyService]
})
export class AppModule {}

Once the example is running you can see the log output

{"level":50,"time":1677579321632,"pid":21361,"hostname":"GuyL-Mac-8.local","reqId":"req-1","context":"AppController","foo":"bar","msg":"baz qux"}

I hope this helps

[iamolegga]

Thanks, will get back to this soon

[saltedsword]

i'm stuck on this too, waiting for your good news!

Thanks, will get back to this soon

[iamolegga]

Sorry, still struggling to find time for this as I'm not using the fastify adapter (and I recommend switching to express if possible, it works more stable and has fewer open issues for this lib). In the meantime PRs are welcome.

[ghost]

Hi everyone, I found a root cause of this.

Fastify generates the res.id on its own, and in pino-http library, they have a check. If id already exists - then use it, otherwise generate one using a default method or custom.

also created a simple test in nest-pino, probably will be useful for someone

import { Controller, Get } from '@nestjs/common';
import { PinoLogger } from '../src';
import { platforms } from './utils/platforms';
import { TestCase } from './utils/test-case';

describe('override gen req id method', () => {
  for (const PlatformAdapter of [platforms[1]]) {
    describe(PlatformAdapter.name, () => {
      it('check the gen req id is matched with overwritten', async () => {
        @Controller('/')
        class TestController {
          constructor(private readonly logger: PinoLogger) {}
          @Get()
          get() {
            // need to work in general, but due to some code specific logic in pino-http, not working in fastify, because fastify setting a default id for req on it's own
            expect(this.logger.logger.bindings().req.id).toEqual(1);
          }
        }

        const logs = await new TestCase(new PlatformAdapter(), {
          controllers: [TestController],
        })
          .forRoot({
            pinoHttp: {
              genReqId: (req, res) => {
                return 1;
              },
              quietReqLogger: true,
              customAttributeKeys: {
                reqId: 'requestId'
              }

            }
          })
          .run();

        console.log()
      });
    });
  }
});

regarding the workaround, in my case, I'm just implementing genReqId function in fastify adapter itself.

  const app = await NestFactory.create<NestFastifyApplication>(
    AppModule,
    new FastifyAdapter({
      genReqId: (req) => {
        return '1';
      },
    }),
    {},
  );