[QUESTION] Middleware binding on graphql requests?

[allenhartwig]

[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 saw it mentioned in this issue that the module should work on graphql requests, however, as far as I can tell, middleware applied via MiddlewareConsumer is not executed when using the nestjs/graphql module. While the logger will work, there is no instance bound to the request from asynclocalstorage, and using the assign method result in an error being thrown.

Is my understanding incorrect? Does something special need to be done to get this functional on graphql requests? I'm thinking the bindLoggerMiddleware needs to be exposed so it can be bound by the graphql context.

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

n/a

[allenhartwig]

To work around this I have created the following:

logger.middleware.ts

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

export function loggerMiddleware(pinoHttpConfig) {
  return (req, res, next) => {
    const pinoMw = pinoHttp(pinoHttpConfig as any);
    // eslint-disable-next-line @typescript-eslint/ban-ts-comment
    // @ts-ignore
    PinoLogger.root = pinoMw.logger;
    pinoMw(req, res, () => {
      storage.run(new Store(req.log), () => {
        next();
      });
    });
  };
}

Then used in main.ts as app.use(loggerMiddleware(myPinoHttpConfig).

This is working, however, the middleware is now double bound on http controller requests therefore creating duplicate log entries. It would be great if there was a way to disable the middleware registration and expose it instead to main.ts to be bound there for those that use graphql.

[allenhartwig]

Adding exclude: ['/(.*)'] to the module config effectively disabled the middleware and the double logging, however, this feels very hacky. Looking forward to your suggestion on how to better implement nestjs-pino for use in a graphql environment.

[iamolegga]

Just checked this on my current project. It works, there is request data in logs:

[2022-01-22T19:06:13.270Z] INFO (83538 on ...): foo bar baz
    context: "UserResolver"
    req: {
      "id": 2,
      "method": "POST",
      "url": "/graphql",
      "query": {},
      "params": {
        "0": "graphql"
      },
      "headers": {
        "host": "localhost:5000",
        "cookie": "sid=...",
        "origin": "electron://altair",
        "user-agent": "Mozilla/5.0 ..."
      },
      "session": {
        "user": null
      }
    }

You can try to change the order of your modules. Logger module should stand before graphql module. Closing, but feel free to ask more questions if you have any

[allenhartwig]

My logger module is imported before the graphql module.

@Module({
  imports: [
    HealthModule,
    AuthModule,
    CacheModule,
    CqrsModule,
    TracingModule,
    LoggerModule,
    ConfigModule.forRoot({
      load: [AppConfig],
      cache: true,
    }),
    GraphqlModule,
    ...

Are you using @nestjs/graphql?

[allenhartwig]

My comment about MiddlewareConsumer not being compatible was based on this conversation and the behavior I observed.

[allenhartwig]

For reference, this is the contents of LoggerModule:

import { Global, Module } from '@nestjs/common';
import { ConfigModule, ConfigService } from '@nestjs/config';
import { LoggerModule as PinoModule } from 'nestjs-pino';
import LoggerConfig from '@app/modules/logger/logger.config';

@Global()
@Module({
  imports: [
    ConfigModule.forFeature(LoggerConfig),
    PinoModule.forRootAsync({
      imports: [ConfigModule],
      useFactory: (config: ConfigService) => config.get('logger').pino,
      inject: [ConfigService],
    }),
  ],
})
export class LoggerModule {}

and GraphqlModule

import { Module } from '@nestjs/common';
import { GraphQLModule } from '@nestjs/graphql';
import { DataloaderModule } from '@app/modules/graphql/dataloader/dataloader.module';
import { DataloaderService } from '@app/modules/graphql/dataloader/dataloader.service';
import { AuthFieldMiddleware } from '@app/modules/auth';
import { GqlModuleOptions } from '@nestjs/graphql/dist/interfaces/gql-module-options.interface';
import { ConfigModule, ConfigService } from '@nestjs/config';
import AppConfig from '../../app.config';

@Module({
  imports: [
    GraphQLModule.forRootAsync({
      imports: [DataloaderModule, ConfigModule.forFeature(AppConfig)],
      inject: [DataloaderService, ConfigService],
      useFactory: (
        dataloaderService: DataloaderService,
        config: ConfigService,
      ): GqlModuleOptions => ({
        autoSchemaFile: true,
        sortSchema: true,
        cors: config.get('app').cors,
        bodyParserConfig: false, //needs to be disabled per Mikro Orm docs: https://mikro-orm.io/docs/usage-with-nestjs/#request-scoping-when-using-graphql
        buildSchemaOptions: {
          fieldMiddleware: [AuthFieldMiddleware],
        },

        context: ({ req, res, payload, connection }) => ({
          req,
          res,
          payload,
          connection,
          loaders: dataloaderService.createLoaders(),
        }),
      }),
    }),
  ],
  providers: [],
  exports: [GraphQLModule],
})
export class GraphqlModule {}

[iamolegga]

Are you using @nestjs/graphql?

yes

import { Logger } from '@nestjs/common';
import { Context, Query, Resolver } from '@nestjs/graphql';

@Resolver(() => UserDTO)
export class UserResolver {
  private readonly logger = new Logger(UserResolver.name);

maybe as a first step just try to change the js sources in npm of pino-logger and graphql modules to check in which order they are applied. As your root wrapper modules import target modules it's simply could be disordered, as nestjs has no warranty on modules' middleware order. Or you can just try to move the logger's module as the first imported module without any wrappers 🤷‍♂️

[allenhartwig]

Ok thanks for your help. If the MiddlewareConsumer should work with @nestjs/graphql, that gives me something to work with.

[julestruong]

Just checked this on my current project. It works, there is request data in logs:

[2022-01-22T19:06:13.270Z] INFO (83538 on ...): foo bar baz
    context: "UserResolver"
    req: {
      "id": 2,
      "method": "POST",
      "url": "/graphql",
      "query": {},
      "params": {
        "0": "graphql"
      },
      "headers": {
        "host": "localhost:5000",
        "cookie": "sid=...",
        "origin": "electron://altair",
        "user-agent": "Mozilla/5.0 ..."
      },
      "session": {
        "user": null
      }
    }

You can try to change the order of your modules. Logger module should stand before graphql module. Closing, but feel free to ask more questions if you have any

@iamolegga On your logs, i can't see any details about query or params :(
That is not very useful informations

[iamolegga]

@julestruong if you need such info you have to use plugins. Here is the reference from my current project:

import { Logger } from '@nestjs/common';
import { Plugin } from '@nestjs/graphql';
import { GraphQLRequestContext } from 'apollo-server-core';
import {
  ApolloServerPlugin,
  GraphQLRequestListener,
  GraphQLRequestContextDidEncounterErrors,
} from 'apollo-server-plugin-base';

@Plugin()
export class GraphQLLogger implements ApolloServerPlugin {
  private readonly logger = new Logger(GraphQLLogger.name);

  async requestDidStart(
    startCtx: GraphQLRequestContext,
  ): Promise<GraphQLRequestListener> {
    return new Listener(
      {
        query: startCtx.request.query,
        operationName: startCtx.request.operationName,
      },
      this.logger,
      // bad bad bad bad typings in lib
    ) as unknown as GraphQLRequestListener;
  }
}

class Listener<T = unknown>
  // bad bad bad bad typings in lib
  implements
    Pick<GraphQLRequestListener<T>, 'didEncounterErrors' | 'willSendResponse'>
{
  private readonly start: number;

  constructor(
    private readonly logData: Record<string, unknown>,
    private readonly logger: Logger,
  ) {
    this.start = Date.now();
  }

  async didEncounterErrors(
    errorsCtx: GraphQLRequestContextDidEncounterErrors<T>,
  ): Promise<void> {
    this.logData.errors = errorsCtx.errors;
  }

  async willSendResponse(): Promise<void> {
    this.logger.log(
      {
        graphql: this.logData,
        responseTime: Date.now() - this.start,
      },
      this.logData.errors ? 'request errored' : 'request completed',
    );
  }
}

also I recommend add to config:

  autoLogging: {
    ignorePaths: [
      // ...

      '/graphql',
    ],
  },

[julestruong]

Thx for the implementation, can you tell me more about why you recommend to ignore autologging for graphql ?

[iamolegga]

@julestruong current plugin will work pretty the same as autologging, but with your custom data. It's just to prevent log duplication, but it's up to you

[kerituni12]

Just checked this on my current project. It works, there is request data in logs:

[2022-01-22T19:06:13.270Z] INFO (83538 on ...): foo bar baz
    context: "UserResolver"
    req: {
      "id": 2,
      "method": "POST",
      "url": "/graphql",
      "query": {},
      "params": {
        "0": "graphql"
      },
      "headers": {
        "host": "localhost:5000",
        "cookie": "sid=...",
        "origin": "electron://altair",
        "user-agent": "Mozilla/5.0 ..."
      },
      "session": {
        "user": null
      }
    }

You can try to change the order of your modules. Logger module should stand before graphql module. Closing, but feel free to ask more questions if you have any

Can you add sample code with graphql, it took me a day to solve this problem, i tried some solutions above but its not working as expected.

I got error when trying to use logger.assign and logger middleware solution but req as res wasn't attached to result just {"level":"info","time":1651615898827,"pid":48107,"hostname":"kin","context":"RoleResolver"}

[iamolegga]

@kerituni12 answered in #936

[rubiin]

@iamolegga an example will be very useful

[iamolegga]

@rubiin sure. I think it's not so hard to add it based on the comment above

[rubiin]

@iamolegga cant seem to piece it back together. How would i use that

[rubiin]

pinoHttpConfig

pinoHttpConfig can you share its value as well

[fhosen]

Ok thanks for your help. If the MiddlewareConsumer should work with @nestjs/graphql, that gives me something to work with.

Hey, sorry to reply at a question that has been closed for such long time, but I am facing the same issue and ended up here 😅 .

Using the approach you mentioned here worked, but I was wondering if you found a better solution.

Between, thanks @iamolegga for this amazing logger for NestJS!