[BUG] Request context not working when using FastifyAdapter

[itheodoro]

[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?
I'm using NestJS with Fastify. nestjs-pino works pretty well with HTTP GET requests and with other HTTP requests that doesn't have a body. When requests have a body, the logger does not brings context and only prints the basic log message, even when log is invoked inside the request context.

What is the expected behavior?
When logging inside a request context, all log entries should have the correct context.

• Correct log entry for request without body:

{"level":30,"time":1631560507217,"pid":448510,"hostname":"host","req":{"id":"req-1","method":"GET","url":"/","headers":{"content-type":"application/json","accept":"*/*","cache-control":"no-cache","host":"localhost:5000","accept-encoding":"gzip, deflate, br","connection":"keep-alive","content-length":"20"},"remoteAddress":"127.0.0.1","remotePort":35350},"context":"AppController","msg":"Hi from getHello"}

• Incorrect log entry for request with body:

{"level":30,"time":1631560533607,"pid":448510,"hostname":"host","context":"AppController","msg":"Hi from postHello"}

Please provide minimal example repo. Without it this issue will be closed
Example repo with log in app.controller.ts

Please mention other relevant information such as Node.js version and Operating System.
Node.js version: v14.17.6
OS: Ubuntu 20.04.3 LTS
nestjs-pino version: ^2.2.0
@nestjs/platform-fastify version: ^8.0.6

Important to mention that the wrong behavior doesn't occurs when using Nest with Express.
I also noticed a possible fix, but I don't know if it could cause some issue since I'm not very familiar with AsyncLocalStorage. The possible fix consists in replace AsyncLocalStorage run by AsyncLocalStorage enterWith method in LoggerModule.

Thanks for creating such a helpful package! 🙏

[iamolegga]

@itheodoro hi, have you tried to play with routing params

WARNING
The fastify package uses the latest version of the path-to-regexp package, which no longer supports wildcard asterisks . Instead, you must use parameters (e.g., (.), :splat*).

looks like the problem is that nest adapters use different routing libs, and it doesn't provide any clean way to detect which adapter is used currently to set proper default routing params, so here some basic routing params are set that works for both express and fastify in tests

[itheodoro]

Hi @iamolegga, thanks for your reply.

I tried to configure routing params to match all available routes and got the same results as before. Is this what you suggest or I misunderstood something?

LoggerModule.forRoot({
    forRoutes: [
        {
            path: '(.*)',
            method: RequestMethod.ALL,
        },
    ],
})

With the above code, this log is also displayed without req object. On the other hand, the automatic request log (the one that displays res object) is still working fine and including the correct context.

[iamolegga]

interesting, will look deeper into this

[itheodoro]

Thanks! Let me know if I can help with something.

Just another behavior that may help is that PinoLogger.assign method throws an error with the following message in the same scenario: PinoLogger: unable to assign extra fields out of request scope.

[sgrigorev]

Hi! Do you have any updates regarding the issue?

[iamolegga]

Sorry, not yet. Not sure if will do in the nearest future, but anyone may feel free to investigate and fix this

[jasyes]

It's looks like there is a bug in latest versions of @nestjs/platform-fastify 8.1.2. The Middleware from module do not fire.
In NestJS github the issue was reported then probably resolved in version 8.0.11 however than Kamil revert commit with bug fix.
However after research I found the workaround.

in main.ts you can add global middleware and use pino from Fastify.

import {storage, Store} from 'nestjs-pino/storage'
import pino from 'pino';

async function bootstrap() {
    const logger = pino({
      level: process.env.NODE_ENV !== 'production' ? 'debug' : 'info',
    })
    const app = await NestFactory.create<NestFastifyApplication>(ApplicationModule, new FastifyAdapter({
      logger,
    }), {
      bufferLogs: true,
    });
    app.useLogger(app.get(Logger));
    app.use((
      req: any,
      _:any,
      next: ()=> void,
    ) => {
      // @ts-ignore
      storage.run(new Store(req.log), next);
    });
   await app.listen(PORT, '0.0.0.0');
}
bootstrap();

[iamolegga]

thanks @jasyes closing this as this is not a bug of the current lib, but will pin it in issues so everyone can see it. Please ping me here when this bug will be fixed.

[thomaschaaf]

@jasyes have you created an issue in the nestjs repo? can you also post where the commit was reverted?

[jasyes]

The main issue was that different version of fastify installed as dependency of @nestjs/platform-fastify and as dependency for project.

[adworacz]

I just encountered this bug myself, thanks for pinning this issue!

Looks like it's still not fixed upstream.

[n4an]

Hey, you @tomtastico, @iamolegga, @SirReiva !

How to do that nestjs/nest#8809 (comment)

Who undrestand how to reproduce that problem without any third-party libraries?

[n4an]

@jmcdo29 thanks, but for that I needed to get a ban.

These mens and womens can when want to do something.

[adworacz]

Based on @jmcdo29's investigation in this issue, it appears that the root cause may be because of how the FastifyRequest wraps the native Node IncomingRequest object.

In order to access attach properties properly to request for Fastify, they should be retrieved from request.raw.foo instead of request.foo.

@iamolegga Does this make sense to you? Perhaps some changes need to be made to the middleware to adapt based on which adapters (Express vs Fastify) is in use?

[jmcdo29]

Another option, just as an FYI, would be to use an onRequest hook for Fastify, though f I recall the onRequest hook doesn't have support for path mapping. I've done this in nest-cookies as a way to manage cookies before Nest added support for @Res({ passthrough: true })

[iamolegga]

Thank you for the investigation. So, it looks like this is a bug in this library, not the framework. I'm a bit busy now (will have time next week) but if someone knows what to do, please open PR (with correct tests), I'll check it asap.

[iamolegga]

FYI https://github.com/fastify/middie/issues/124

[itheodoro]

FYI fastify/fastify#3571

[iamolegga]

Thanks, but I think it's enough of FYI's here, it won't help, only spam notifications, I'm already subscribed to all the related issues and watching the situation.

It looks like we only need to change the storage.run with storage.enterWith in the code. But that thing should be tested correctly, as current tests pass for fastify, so the main challenge here is to write correct tests for this first, check that current behavior is broken, and the new one is correct.

[itheodoro]

If I get it right, Fastify v3.25.2 already solves the issue. Since we are using Fastify via platform-fastify, a new version of the package with updated Fastify version (>= v3.25.2) must solve the problem without the need of implementations here in nestjs-pino. Also, the need of a new version of platform-fastify was already pointed here.

[itheodoro]

Closing this issue since @nestjs/[email protected] fixes the wrong behavior by updating fastify version. Thanks all!

[iamolegga]

Cool, @itheodoro have you tested this fix already?

[itheodoro]

Yes, I've tested and it's working fine, @iamolegga 🎉

[adworacz]

For anyone else who stumbles across this issue, I was still having issues with logs not having request context information, as shown in the OP.

I finally tracked it down to having fastify in my devDependencies. If I removed that AND deleted my node_modules folder AND deleted my package-lock.json folder (forcing it to be completely rebuild) THEN I started receiving request context information accordingly.

I was able to replicate this with a fresh NestJS project too, where simply having the fastify dep in my package.json was enough to break the request context being added to my logs.

Hope this helps someone else!

[yanivfranco]

@adworacz Literally life saver!!!
I already encountered some issues when having both fastify and @nestjs/platform-fastify present, and it is always consumed so much time & energy to reach this conclusion

Thanks