[FEATURE REQUEST] Logger usage outside HTTP context

[mentos1386]

• [x] I've read the docs of nestjs-pino
• [x] I've read the docs of pino
• [x] I couldn't find the same question about nestjs-pino

Question

I'm trying to use logger.assign outside of HTTP context. Specifically, inside sqs consumer's handleMessage function.

I figured out with the help of #788 to initiate the storage.run on my own. The problem was that i don't have access to req.log so i used PinoLogger.root instead. Is this supposed to be used like this?

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

---

    this.consumer = Consumer.create({
      // this magic creates AsyncLocalStorage context
      // for nestjs-pino to work with. It allows the use
      // of this.logger.assign() method.
      handleMessage: message =>
        storage.run(new Store(PinoLogger.root), () =>
          this.processMessage(message),
        ),
    });

It seems to work fine. But want to make sure we won't break something in strange ways.

I guess this also relates to @nestjs/bull and @nestjs/microservices are those environments supported? As they are similarly not inside HTTP context (not passing middlewares afaik).

Edit: If this is a valid usage, maybe it could be wrapped in a nicer withNestPinoContext(() => this.processMessage(message)) like function.

[iamolegga]

Desired behavior is not supported at the moment. You can try any hacks (as presented above) to make it work but on your own risk. This is not tested and not supported.

For this feature we need something similar to pino-http-like settings with a lot of settings beside pino-related ones. So this is huge feature and it need a lot of time for implementation. Unfortunately I'm not able to invest in this at the moment. But maybe this year on my current project we will need such feature too, then I think we can invest some time for this. But that's not 100%. In case anyone would like to implement this, feel free to open detailed RFC for this first, before opening PR.

Will change this issue to feature request.

[jbbeal]

I'm getting this same error message running unit tests. I'm using Nest's TestingModule like so:

    moduleRef = await Test.createTestingModule({
      imports: [
        LoggerModule.forRoot({ pinoHttp: { level: 'debug' } }),
        MongooseModule.forRoot('mongodb://localhost/tracker-test', { autoIndex: true }),
        MongooseModule.forFeature([{ name: Category.name, schema: CategorySchema }]),
      ],
      providers: [CategoryService],
    }).compile();

and have PinoLogger injected into my service via the @InjectPinoLogger tag. When my code calls logger.assign, it fails with the "unable to assign extra fields out of request scope" message. I'll read some of the other linked issues and see if I can figure out a workaround.

[iamolegga]

OK, in next month or two I'm going to investigate if it's possible to make such feature work with different microservices' transports including custom strategies.

For implementing this feature in a clear way we need middlewares for microservices to be landed in nest. Until then this solution could be used.

[KieronWiltshire]

@iamolegga consider setting up a bounty program. I'd be willing to contribute funding for you to do this if you'd prefer to handle it yourself.

[iamolegga]

@KieronWiltshire answering your question from different issue

Some thought on design for this feature:

I believe the configuration for microservices should be as close as possible to the configuration of pino-http.

Existing pino-http parameters could be:

• reused (e.g. autoLogging, stream, logger etc)
• skipped (?)
• duplicated with different arguments: req/res arguments should be changed to message (e.g. genReqId, customLogLevel, autoLogging.ignore, customReceivedMessage, etc).

Maybe some extra parameters could be added?

Maybe this should be done in different npm package and reused here, the same as pino-http is reused.

[KieronWiltshire]

@iamolegga to be honest... I'm not sure why this approach was even taken. Surely it would've just made sense to pass the pinojs parameters through the module and allow fully interoperability with the official pinojs package. Maybe some of your thoughts on this initial implementation would help me understand more here.

[iamolegga]

@iamolegga consider setting up a bounty program. I'd be willing to contribute funding for you to do this if you'd prefer to handle it yourself.

I'm ok to handle it by myself, but this needs time to make a good API for end-users and good internal design.

So far due to personal reasons I'm not able to invest such time in this feature not in working hours, I hope for your understanding. But to work on this in working hours this needs to be prioritized on my current project where we are using this library, and I believe won't happen in the nearest future as we are building and starting MVP at the moment.

Answering your question: thank you for the suggestion, but it won't work as this is not about money but time. Anyway if someone wants to thank me for the work that's already done in this library please consider donating to Ukraine by the links in docs header 🙏

@iamolegga to be honest... I'm not sure why this approach was even taken. Surely it would've just made sense to pass the pinojs parameters through the module and allow fully interoperability with the official pinojs package. Maybe some of your thoughts on this initial implementation would help me understand more here.

sorry, didn't get what do you mean. If you have a better solution you are more than welcome to fork it or open PR

[KieronWiltshire]

@iamolegga sorry, didn't mean to insult. I'm glad you've created this project, just looking to improve on what you've already built.

sorry, didn't get what do you mean. If you have a better solution you are more than welcome to fork it or open PR

Basically... this package assumes the logging through HTTP or now at this point, microservice, but what about during queue workers etc... what I'm saying is, wouldn't it make more sense to just support pinojs as the module itself, or even better allow the passing of a pinojs instance from forRoot or forRootAsync

Would you like to converse over something like discord for this? or keep it here?

[mentos1386]

@KieronWiltshire please keep the conversation here, or provide a summary in case conversation would take place somewhere else. I would like to know where this is going as well :)

[iamolegga]

sorry, didn't mean to insult

no worries 🙂

this package assumes the logging through HTTP or now at this point, microservice, but what about during queue workers etc.

Sure, queue workers you mean bull, right? Yes, basically we have to create some generic factory that will call parameters methods with the provided argument type. It could be bull's job, microservice's messages and events or any other context.

what I'm saying is, wouldn't it make more sense to just support pinojs as the module itself, or even better allow the passing of a pinojs instance from forRoot or forRootAsync

could you please describe more on this? What API are you expecting?

Would you like to converse over something like discord for this? or keep it here?

agree with @mentos1386 let's keep it here for now

[KieronWiltshire]

@iamolegga so the logger service should just implement a PinoJS instance right, where the instance is instantiated through the module forRoot and forRootAsync functions. Ideally, I should just be able to inject logger into my app, have all the implementation details hidden, and if I have say pino as my logger implementation with transports to sentry setup, all that should just be handled and abstracted away from me. I should be able to use the logger literally anywhere.

[iamolegga]

So what's the difference from current implementation that doesn't fit your needs? You can use NestJS built-in logger as a facade for pino implementation. If you don't need automatic logging just disable it with autoLogging field and that's it. You can use this logger in any context already.

Current feature request is about possibility to create pino-http-like behavior for other contexts:

1. Automatic logging with desired auto generated fields
2. Adding same extra fields to any logs that were created in same request context

[KieronWiltshire]

@iamolegga Yeah this was kind of why I created a new issue :P You can't provide transports. I created a Logtail transport for PinoJS. I can't plug that in :P

[iamolegga]

Have you tried something like:

    LoggerModule.forRootAsync({
      imports: [ConfigModule],
      inject: [ConfigService],
      useFactory: async (config: ConfigService) => {
        return {
          pinoHttp: {
            logger: pino(pino.transport({
              target: 'my-transport',
              options: config.transportOptions
            })),
          },
        };
      }
    })

https://getpino.io/#/docs/transports https://github.com/pinojs/pino-http#api

If this doesn't work please open an issue with minimal example repo with some naive transport. I believe all next discussions should be continued there, as I can see that the current one is not related to your case

[KieronWiltshire]

@iamolegga that only allows transport for the pino-http module. Would you consider reopening my issue?

[iamolegga]

that only allows transport for the pino-http module

@KieronWiltshire could you please open an issue with the bug type and a minimal example repo?

Would you consider reopening my issue?

let's open a new issue with appropriate type and end this discussion here

[KieronWiltshire]

@iamolegga no need for a separate issue. After looking at the code I see what I need to do. I'll show you code snippet so you understand, but this seems ridiculously backwards. I think you should consider creating a pino instance and attaching the pino-http package to it instead of the other way around.

Here:

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

@Module({
  imports: [
    ConfigModule.forRoot({
      cache: true,
      isGlobal: true,
      load: [
        appConfig,
        databaseConfig,
        redisConfig,
        sentryConfig
      ]
    }),
    LoggerModule.forRootAsync({
      imports: [ConfigModule],
      useFactory: (config: ConfigService) => {
        const pinoLogger = pino(transport({
            target: "pino-sentry-transport",
            options: {
              sentry: {
                dsn: "https://<key>:<secret>@sentry.io/<project>",
                // aditional options for sentry
              },
              withLogRecord: true, // default false - send the log record to sentry as a context.(if its more then 8Kb Sentry will throw an error)
              tags: ['id'], // sentry tags to add to the event, uses lodash.get to get the value from the log record
              context: ['hostname'], // sentry context to add to the event, uses lodash.get to get the value from the log record,
              minLevel: 40, // which level to send to sentry
            }
        }));
        return {
          pinoHttp: {
            logger: pinoLogger,
          }
        }
      },
      inject: [ConfigService]
    }),
  ],
})
export class AppModule implements NestModule {}

Because of the way you instantiate a pino logger, I have to pass it through the pinoHttp.logger option. Realistically, I should just be able to provide a pino instance without going through pinoHttp. It doesn't really matter, but I feel like it's something that could be improved upon.

[clintonb]

@iamolegga no need for a separate issue. After looking at the code I see what I need to do. I'll show you code snippet so you understand, but this seems ridiculously backwards. I think you should consider creating a pino instance and attaching the pino-http package to it instead of the other way around.

Here:

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

@Module({
  imports: [
    ConfigModule.forRoot({
      cache: true,
      isGlobal: true,
      load: [
        appConfig,
        databaseConfig,
        redisConfig,
        sentryConfig
      ]
    }),
    LoggerModule.forRootAsync({
      imports: [ConfigModule],
      useFactory: (config: ConfigService) => {
        const pinoLogger = pino(transport({
            target: "pino-sentry-transport",
            options: {
              sentry: {
                dsn: "https://<key>:<secret>@sentry.io/<project>",
                // aditional options for sentry
              },
              withLogRecord: true, // default false - send the log record to sentry as a context.(if its more then 8Kb Sentry will throw an error)
              tags: ['id'], // sentry tags to add to the event, uses lodash.get to get the value from the log record
              context: ['hostname'], // sentry context to add to the event, uses lodash.get to get the value from the log record,
              minLevel: 40, // which level to send to sentry
            }
        }));
        return {
          pinoHttp: {
            logger: pinoLogger,
          }
        }
      },
      inject: [ConfigService]
    }),
  ],
})
export class AppModule implements NestModule {}

Because of the way you instantiate a pino logger, I have to pass it through the pinoHttp.logger option. Realistically, I should just be able to provide a pino instance without going through pinoHttp. It doesn't really matter, but I feel like it's something that could be improved upon.

I'm not sure why this answer is marked as off-topic, but this is the ideal solution. I do the following:

1. Create a "root" pino logger with the relevant configuration.
2. Pass this root logger as pinoHttp.logger.

[michaeljauk]

Hey @iamolegga any update on this? :) Or any recommended workaround?

[iddan]

My current workaround: Using withLoggerContext decorator over the functions I would like to use context. Example:

@withLoggerContext
foo() {

Here is the code for withLoggerContext:

import { Store, storage } from 'nestjs-pino/storage';
import logger from './pino-logger-instance'; // this should be the same pino instance nestjs-pino uses

export const withLoggerContext: MethodDecorator = (
  target,
  propertyKey,
  descriptor,
) => {
  const methodFunc = descriptor.value;
  if (!methodFunc) {
    return;
  }
  const newMethodFunc = function (...args) {
    // @ts-expect-error
    storage.run(new Store(logger.child({})), () => methodFunc.call(this, args));
  };
  // @ts-expect-error
  descriptor.value = newMethodFunc;
};

[clintonb]

Here is a version of WithLoggerContext that works for async functions and properly pass through all arguments:

import { Store, storage } from 'nestjs-pino/storage';
import rootPinoLogger from './pino-logger-instance'; // this should be the same pino instance nestjs-pino uses

export function WithLoggerContext() {
  return function (
    target,
    key: string | symbol,
    descriptor: PropertyDescriptor
  ) {
    const methodFunc = descriptor.value;
    if (!methodFunc) {
      return descriptor;
    }

    if (methodFunc.constructor.name === 'AsyncFunction') {
      descriptor.value = async function (...args) {
        return storage.run(new Store(rootPinoLogger.child({})), async () =>
          methodFunc.apply(this, args)
        );
      };
    } else {
      descriptor.value = function (...args) {
        return storage.run(new Store(rootPinoLogger.child({})), () =>
          methodFunc.apply(this, args)
        );
      };
    }

    return descriptor;
  };
}

[conioX]

can you share

import rootPinoLogger from './pino-logger-instance';

@iddan