nestjs-pino: [BUG] Request context not working when using FastifyAdapter

[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! 🙏

About this issue

Original URL
State: closed
Created 3 years ago
Comments: 25 (8 by maintainers)

Most upvoted comments

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.

iamolegga on Dec 23, 2021

Closing this issue since @nestjs/platform-fastify@8.2.6 fixes the wrong behavior by updating fastify version. Thanks all!

itheodoro on Jan 20, 2022

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();

jasyes on Nov 7, 2021

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!

adworacz on Feb 11, 2022

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

itheodoro on Jan 20, 2022

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 on Dec 27, 2021

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

iamolegga on Dec 22, 2021

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?

adworacz on Dec 22, 2021

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

These mens and womens can when want to do something.

n4an on Dec 21, 2021

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

How to do that https://github.com/nestjs/nest/issues/8809#issuecomment-997980588

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

n4an on Dec 21, 2021

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

iamolegga on Oct 13, 2021

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.

itheodoro on Sep 15, 2021