feat: support graphql in request interceptor

package.json

@@ -33,12 +33,15 @@
   "dependencies": {
     "@nestjs/common": "^9.3.12",
     "@nestjs/core": "^9.3.12",
+    "@nestjs/graphql": "^11.0.0",
     "bunyan": "^1.8.15",
     "reflect-metadata": "^0.1.13",
     "request-ip": "^3.3.0",
     "rxjs": "^7.8.0"
   },
   "devDependencies": {
+    "@apollo/server": "^4.7.0",
+    "@nestjs/apollo": "^11.0.0",
     "@nestjs/cli": "^9.3.0",
     "@nestjs/config": "^2.3.1",
     "@nestjs/platform-express": "^9.3.12",
@@ -53,6 +56,7 @@
     "eslint": "^8.36.0",
     "eslint-config-prettier": "^8.8.0",
     "eslint-plugin-prettier": "^4.2.1",
+    "graphql": "^16.6.0",
     "jest": "^29.5.0",
     "prettier": "^2.8.6",
     "rimraf": "^4.4.1",

src/logger.interceptor.ts

@@ -9,6 +9,7 @@ import * as util from 'util';
 
 import { LoggerConfig } from './logger.interfaces';
 import { isMatch } from './logger.utils';
+import { GqlContextType, GqlExecutionContext } from '@nestjs/graphql';
 
 export class RequestInterceptor implements NestInterceptor {
   private readonly _logger: Bunyan;
@@ -24,12 +25,22 @@ export class RequestInterceptor implements NestInterceptor {
     next: CallHandler<any>,
   ): Observable<any> | Promise<Observable<any>> {
     const start = new Date();
-    const ctx = context.switchToHttp();
-    const req = ctx.getRequest<Express.Request>();
-    const res = ctx.getResponse<ServerResponse>();
+    let req: Express.Request;
+    let res: ServerResponse | undefined;
+    if (context.getType() === 'http') {
+      const ctx = context.switchToHttp();
+      req = ctx.getRequest<Express.Request>();
+      res = ctx.getResponse<ServerResponse>();
+    } else if (context.getType<GqlContextType>() === 'graphql') {
+      const ctx = GqlExecutionContext.create(context).getContext();
+      req = ctx.req;
+    } else {
+      return next.handle();
+    }
+
     const method = req.method;
-    const url = req.url;
-    const route = req.route.path;
+    const url = req.originalUrl;
+    const route = context.getType() === 'http' ? req.route.path : req.baseUrl;
 
     const options = this.options;
     const reqId = options.genReqId
@@ -84,7 +95,7 @@ export class RequestInterceptor implements NestInterceptor {
       this._logger.info({
         ...common,
         'short-body': body && buildShortBody(body, options.shortBodyLength),
-        'status-code': res.statusCode,
+        'status-code': context.getType() === 'http' ? res.statusCode : 200,
       });
     };
     return next

test/app.e2e-spec.ts

@@ -14,11 +14,15 @@ describe('AppController (e2e)', () => {
     await app.init();
   });
 
+  afterEach(() => {
+    jest.restoreAllMocks();
+  });
+
   afterAll(async () => {
     await app.close();
   });
 
-  it('should be able to track req,resp', async () => {
+  it('should be able to track restful req,resp', async () => {
     const loggerMock = jest
       .spyOn(Logger.prototype, 'info')
       .mockImplementation();
@@ -42,7 +46,41 @@ describe('AppController (e2e)', () => {
       'transactionId',
       'test-txn-id',
     );
-    loggerMock.mockRestore();
+  });
+  it('should be able to track graphql req, resp', async () => {
+    const loggerMock = jest
+      .spyOn(Logger.prototype, 'info')
+      .mockImplementation();
+    const resp = await request(app.getHttpServer())
+      .post('/graphql')
+      .set('x-transaction-id', 'test-txn-id')
+      .send({
+        query: `
+        {
+          hello
+        }`,
+      })
+      .expect(200);
+    expect(resp.body).toEqual({
+      data: {
+        hello: 'hello',
+      },
+    });
+    expect(loggerMock).toHaveBeenCalledTimes(2);
+    // first call
+    expect(loggerMock.mock.calls[0][0]).toHaveProperty('direction', 'inbound');
+    expect(loggerMock.mock.calls[0][0]).toHaveProperty('route', '/graphql');
+    expect(loggerMock.mock.calls[0][0]).toHaveProperty(
+      'transactionId',
+      'test-txn-id',
+    );
+    // second call
+    expect(loggerMock.mock.calls[1][0]).toHaveProperty('direction', 'outbound');
+    expect(loggerMock.mock.calls[1][0]).toHaveProperty('route', '/graphql');
+    expect(loggerMock.mock.calls[1][0]).toHaveProperty(
+      'transactionId',
+      'test-txn-id',
+    );
   });
   it('should skip record log for excludeReqPath', async () => {
     const loggerMock = jest
@@ -52,9 +90,8 @@ describe('AppController (e2e)', () => {
     const resp = await request(app.getHttpServer()).get('/health').expect(200);
     expect(resp.text).toBe('ok');
     expect(loggerMock).toHaveBeenCalledTimes(0);
-    loggerMock.mockRestore();
   });
-  it('should be able to track resp when non-200 status code', async () => {
+  it('should be able to track restful resp when non-200 status code', async () => {
     const loggerInfoMock = jest
       .spyOn(Logger.prototype, 'info')
       .mockImplementation();
@@ -77,10 +114,54 @@ describe('AppController (e2e)', () => {
     expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty('route', '/forbid');
     expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty('status-code', 403);
     expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty('err');
-    loggerInfoMock.mockRestore();
-    loggerErrorMock.mockRestore();
   });
-  it('should be able to record short-body', async () => {
+  it('should be able to track graphql resp when non-200 status code', async () => {
+    const loggerInfoMock = jest
+      .spyOn(Logger.prototype, 'info')
+      .mockImplementation();
+    const loggerErrorMock = jest
+      .spyOn(Logger.prototype, 'error')
+      .mockImplementation();
+
+    const resp = await request(app.getHttpServer())
+      .post('/graphql')
+      .set('x-transaction-id', 'test-txn-id')
+      .send({
+        query: `
+        {
+          forbid
+        }`,
+      });
+    expect(resp.statusCode).toBe(200);
+    expect(resp.body).toMatchObject({
+      errors: [
+        {
+          extensions: {
+            code: 'FORBIDDEN',
+          },
+        },
+      ],
+      data: null,
+    });
+    expect(loggerInfoMock).toHaveBeenCalledTimes(1);
+    expect(loggerErrorMock).toHaveBeenCalledTimes(1);
+    expect(loggerInfoMock.mock.calls[0][0]).toHaveProperty(
+      'direction',
+      'inbound',
+    );
+    expect(loggerInfoMock.mock.calls[0][0]).toHaveProperty('route', '/graphql');
+    expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty(
+      'direction',
+      'outbound',
+    );
+    expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty(
+      'route',
+      '/graphql',
+    );
+    expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty('status-code', 403);
+    expect(loggerErrorMock.mock.calls[0][0]).toHaveProperty('err');
+  });
+  it('should be able to record restful short-body', async () => {
     const loggerMock = jest
       .spyOn(Logger.prototype, 'info')
       .mockImplementation();
@@ -103,14 +184,36 @@ describe('AppController (e2e)', () => {
       'short-body',
       "{ data: { name: 'cathy', gene: 'Persian', age: 4 } }",
     );
-
-    loggerMock.mockRestore();
   });
-  it('should be able to restrict the length of short-body', async () => {
+  it('should be able to record graphql short-body', async () => {
     const loggerMock = jest
       .spyOn(Logger.prototype, 'info')
       .mockImplementation();
     const resp = await request(app.getHttpServer())
+      .post('/graphql')
+      .set('x-transaction-id', 'test-txn-id')
+      .send({
+        query: `{hello}`,
+      })
+      .expect(200);
+    expect(resp.body.data).toEqual({
+      hello: 'hello',
+    });
+    expect(loggerMock).toHaveBeenCalledTimes(2);
+    // first call
+    expect(loggerMock.mock.calls[0][0]).toHaveProperty('direction', 'inbound');
+    expect(loggerMock.mock.calls[0][0]['short-body']).toBe(
+      `{ query: '{hello}' }`,
+    );
+    // second call
+    expect(loggerMock.mock.calls[1][0]).toHaveProperty('direction', 'outbound');
+    expect(loggerMock.mock.calls[1][0]['short-body']).toBe(`'hello'`);
+  });
+  it('should be able to restrict the length of short-body', async () => {
+    const loggerMock = jest
+      .spyOn(Logger.prototype, 'info')
+      .mockImplementation();
+    await request(app.getHttpServer())
       .post('/cats')
       .set('x-transaction-id', 'test-txn-id')
       .send({
@@ -141,7 +244,5 @@ describe('AppController (e2e)', () => {
     // second call
     expect(loggerMock.mock.calls[1][0]).toHaveProperty('direction', 'outbound');
     expect(loggerMock.mock.calls[1][0]['short-body']).toHaveLength(100);
-
-    loggerMock.mockRestore();
   });
 });

test/test-app/app.module.ts

@@ -1,6 +1,9 @@
 import { Module } from '@nestjs/common';
 import { LoggerModule } from '../../src';
 import { AppController } from './app.controller';
+import { GraphQLModule } from '@nestjs/graphql';
+import { ApolloDriver, ApolloDriverConfig } from '@nestjs/apollo';
+import { AppResolver } from './app.resolver';
 
 @Module({
   imports: [
@@ -10,7 +13,14 @@ import { AppController } from './app.controller';
       excludeReqPath: '/health',
       shortBodyLength: 100,
     }),
+    GraphQLModule.forRoot<ApolloDriverConfig>({
+      driver: ApolloDriver,
+      playground: true,
+      autoSchemaFile: true,
+      sortSchema: true,
+    }),
   ],
   controllers: [AppController],
+  providers: [AppResolver],
 })
 export class AppModule {}

test/test-app/app.resolver.ts

@@ -0,0 +1,15 @@
+import { ForbiddenException } from '@nestjs/common';
+import { Query, Resolver } from '@nestjs/graphql';
+
+@Resolver('App')
+export class AppResolver {
+  @Query(() => String)
+  async hello() {
+    return 'hello';
+  }
+
+  @Query(() => String)
+  async forbid() {
+    throw new ForbiddenException();
+  }
+}