Nest.js logger middleware 테스트 (TDD)

할 일 목록 작성 (1)

App.module에서 전역적으로 모든 요청을 기록할 logger middleware를 제작하기 위해 먼저 logger middleware의 할 일 목록을 작성한다.

 

1. LoggerMiddleware 클래스를 만든다.

2. NestMiddleware의 use 메서드에서 next를 호출한다.

 

가장 간단해 보이는 구현부터 시작해서 Red, Green Refactor의 단계를 거치도록 한다.

 

LoggerMiddleware 클래스를 만든다.

[Red]

logger.middleware.spec.ts

describe('LoggerMiddleware', () => {
  it('should be defined', () => {
    expect(LoggerMiddleware).toBeDefined();
  });
});

LoggerMiddleware를 정의하는 것 부터 시작한다.

 

[Green]

logger.middleware.ts

export class LoggerMiddleware {}

logger.middleware.spec.ts

import { LoggerMiddleware } from './logger.middleware';

describe('LoggerMiddleware', () => {
  it('should be defined', () => {
    expect(LoggerMiddleware).toBeDefined();
  });
});

LoggerMiddleware 클래스를 작성하고 logger.middleware.spec.ts에 import 해준다.

테스트가 통과된다.

 

[Refactor]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [LoggerMiddleware],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });
});

refactor는 green을 통과한 테스트를 수정하는 것을 의미하지만, 일단 전반적으로 테스트를 용이하게 하기 위해 테스트 기반을 nest.js의 테스팅 모듈로 바꿔준다.

 

NestMiddleware의 use 메서드에서 next를 호출한다.

[Red]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';
import * as httpMocks from 'node-mocks-http';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;

  const request = httpMocks.createRequest();
  const response = httpMocks.createResponse();
  const next = jest.fn();

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [LoggerMiddleware],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });

  it('should call use method with request, response, next', () => {
    loggerMiddleware.use(request, response, next);

    expect(next).toHaveBeenCalled();
  });
});

use 메서드는 request, response, next를 인자로 받아 next를 호출한다.

일단 node-mocks-http를 사용해서 request, response를 모킹 해주고 next를 jest.fn()으로 모킹 해준다.

 

[Green]

logger.middleware.ts

import { NestMiddleware } from '@nestjs/common';

export class LoggerMiddleware implements NestMiddleware {
  use(request, response, next) {
    next();
  }
}

LoggerMiddleware의 세부적 내용을 구현하지 않고 request, response, next를 인자로 받아 next()를 호출한다.

 

[Refactor]

request, response, next의 타입을 명시 해준다.

logger.middleware.ts

import { NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';

export class LoggerMiddleware implements NestMiddleware {
  use(request: Request, response: Response, next: NextFunction) {
    next();
  }
}

 

할 일 목록 작성 (2)

앞서 두가지의 할 일을 완료했다. 조금 더 구체적인 모듈과 테스트 작성에 들어간다.

 

1. LoggerMiddleware 클래스를 만든다.

2. NestMiddleware의 use 메서드를 구현한다.

3. LoggerMiddleware의 생성자로 winston logger를 주입한다.

4. use 메서드에서 response.on을 호출한다.

 

LoggerMiddleware의 생성자로 winston logger를 주입한다.

[Red]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';
import * as httpMocks from 'node-mocks-http';
import { Logger } from 'winston';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;
  let logger: Logger;

  const request = httpMocks.createRequest();
  const response = httpMocks.createResponse();
  const next = jest.fn();

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [
        LoggerMiddleware,
        {
          provide: WINSTON_MODULE_PROVIDER,
          useValue: {
            info: jest.fn(),
          },
        },
      ],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
    logger = module.get<Logger>(WINSTON_MODULE_PROVIDER);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });

  it('should call use method with request, response, next', () => {
    loggerMiddleware.use(request, response, next);

    expect(next).toHaveBeenCalled();
  });

  it('should have logger inside of middleware', () => {
    expect(loggerMiddleware).toHaveProperty('logger');
    expect(loggerMiddleware['logger']).toBe(logger);
  });
});

LoggerMiddleware에 logger를 constructor로 주입할 것이기 때문에 loggerMiddleware 인스턴스는 'logger'라는 프로퍼티를 갖게 되고, logger라는 이름의 프로퍼티는 WINSTON_MODULE_PROVIDER를 통해 주입된 logger이다. 이때 Logger가 '@nestjs/common'의 Logger가 아니라 'winston'의 Logger인 것에 주의한다.

 

[Green]

logger.middleware.ts

import { Inject, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

export class LoggerMiddleware implements NestMiddleware {
  constructor(@Inject(WINSTON_MODULE_PROVIDER) readonly logger: Logger) {}

  use(request: Request, response: Response, next: NextFunction) {
    next();
  }
}

@inject를 통해 WINSTON_MODULE_PROVIDER를 주입 해주면 테스트가 통과된다.

 

[Refactor]

특별히 개선할 점은 없다.

 

use 메서드에서 response.on을 호출한다.

[Red]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';
import { Logger } from 'winston';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Request, Response, NextFunction } from 'express';
import * as http from 'http';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;
  let logger: Logger;

  const request = {} as unknown as Request;
  const response = new http.ServerResponse(request) as unknown as Response;
  const next = jest.fn() as NextFunction;

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [
        LoggerMiddleware,
        {
          provide: WINSTON_MODULE_PROVIDER,
          useValue: {
            info: jest.fn(),
          },
        },
      ],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
    logger = module.get<Logger>(WINSTON_MODULE_PROVIDER);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });

  it('should call use method with request, response, next', () => {
    loggerMiddleware.use(request, response, next);

    expect(next).toHaveBeenCalled();
  });

  it('should have logger inside of middleware', () => {
    expect(loggerMiddleware).toHaveProperty('logger');
    expect(loggerMiddleware['logger']).toBe(logger);
  });

  it("should call response.on 'finish'", () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(spyResponseOn).toHaveBeenCalledWith('finish', expect.any(Function));

    spyResponseOn.mockRestore();
  });
});

httpMocks는 response.on과 같은 EventEmitter의 사용을 지원하지 않는다. 따라서 response.on을 모킹하여 테스트 해야 하기 때문에 작성하기 난이도가 높은 테스트이다.

 

 

1. response.on의 이해

 

Response는 core.Response를 상속 받는다.

interface Response<
    ResBody = any,
    Locals extends Record<string, any> = Record<string, any>,
> extends core.Response<ResBody, Locals> {}

core.Response는 http.ServerResponse를 상속 받는다.

export interface Response<
    ResBody = any,
    LocalsObj extends Record<string, any> = Record<string, any>,
    StatusCode extends number = number,
> extends http.ServerResponse, Express.Response {...}

http.ServerResponse는 OutgoingMessage를 상속 받는다.

class ServerResponse<Request extends IncomingMessage 
 = IncomingMessage> extends OutgoingMessage<Request> {...}

OutgoingMessage는 stream.Writable를 상속 받는다.

class OutgoingMessage<Request extends IncomingMessage
 = IncomingMessage> extends stream.Writable {...}

Writable은 WritableBase를 상속 받는다.

class Writable extends WritableBase {...}

WritableBase은 NodeJS.WritableStream을 구현한다.

class WritableBase extends Stream implements NodeJS.WritableStream {...}

WritableStream은 EventEmitter를 상속 받는다.

interface WritableStream extends EventEmitter {
            writable: boolean;
            write(buffer: Uint8Array | string, cb?: (err?: Error | null) => void): boolean;
            write(str: string, encoding?: BufferEncoding, cb?: (err?: Error | null) => void): boolean;
            end(cb?: () => void): this;
            end(data: string | Uint8Array, cb?: () => void): this;
            end(str: string, encoding?: BufferEncoding, cb?: () => void): this;
        }

EventEmitter는 이벤트를 등록하는 emitter.on 메서드를 갖는다. 

emitter.on은 emitter.addListener와 동일하며 response.on은 EventEmitter의 on 메서드를 통해 특정 이벤트 발생시의 행위를 등록하는 것으로 볼 수 있다.

 

2. response의 모킹

 

http의 ServerResponse를 구현 해준다. http.d.ts를 참조하면 class ServerResponse는 constructor로 Request를 받는다. 따라서 앞서 만들어둔 request를 프로퍼티로 제공하고 new 생성자를 통해 http.ServerResponse의 인스턴스를 생성한다.

...
const request = {} as unknown as Request;
const response = new http.ServerResponse(request) as unknown as Response;
const next = jest.fn() as NextFunction;
...

 

3. jest.spyOn(response, 'on');

 

Jest의 spyOn 메서드는 특정 객체의 메서드를 감시(spy)하도록 설정한다. 이를 통해 해당 메서드가 호출되었는지, 어떤 인자들로 호출되었는지 등을 검사할 수 있다.

  it("should call response.on 'finish'", () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(spyResponseOn).toHaveBeenCalledWith('finish', expect.any(Function));

    spyResponseOn.mockRestore();
  });

const spyResponseOn = jest.spyOn(response, 'on');을 통해 response의 on 메서드를 감시한다. 이후 loggerMiddleware의 use를 호출하고, emit('finish')로 finish 이벤트를 발생시킨다. spyResponseOn이 호출되는지 확인한 뒤 다른 테스트에서 response.on에 대한 감시가 이전 테스트의 영향을 받지 않도록 mockRestore()를 해준다.

 

[Green]

logger.middleware.ts

import { Inject, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

export class LoggerMiddleware implements NestMiddleware {
  constructor(@Inject(WINSTON_MODULE_PROVIDER) readonly logger: Logger) {}

  use(request: Request, response: Response, next: NextFunction) {
    response.on('finish', () => {
      return;
    });
    next();
  }
}

 

[Refactor]

특별히 개선할 점은 없다.

 

할 일 목록 작성 (3)

winston logger의 주입과 use 메서드의 response.on 호출까지 끝냈다. 마지막 세부 구현만이 남아있다.

 

1. LoggerMiddleware 클래스를 만든다.

2. NestMiddleware의 use 메서드를 구현한다.

3. LoggerMiddleware의 생성자로 winston logger를 주입한다.

4. use 메서드에서 response.on을 호출한다.

5. 'finish' 이벤트가 완료되면 logger의 info를 호출한다.

6. logger.info를 통해 request의 정보를 로깅한다.

 

'finish' 이벤트가 완료되면 logger의 info를 호출한다.

[Red]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';
import { Logger } from 'winston';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Request, Response, NextFunction } from 'express';
import * as http from 'http';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;
  let logger: Logger;

  const request = {} as unknown as Request;
  const response = new http.ServerResponse(request) as unknown as Response;
  const next = jest.fn() as NextFunction;

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [
        LoggerMiddleware,
        {
          provide: WINSTON_MODULE_PROVIDER,
          useValue: {
            info: jest.fn().mockImplementation((text) => {
              console.log(text);
            }),
          },
        },
      ],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
    logger = module.get<Logger>(WINSTON_MODULE_PROVIDER);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });

  it('should call use method with request, response, next', () => {
    loggerMiddleware.use(request, response, next);

    expect(next).toHaveBeenCalled();
  });

  it('should have logger inside of middleware', () => {
    expect(loggerMiddleware).toHaveProperty('logger');
    expect(loggerMiddleware['logger']).toBe(logger);
  });

  it("should call response.on 'finish'", () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(spyResponseOn).toHaveBeenCalledWith('finish', expect.any(Function));

    spyResponseOn.mockRestore();
  });

  it('should call logger.info when finish', async () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(logger.info).toHaveBeenCalled();

    spyResponseOn.mockRestore();
  });
});

방금 작성한 테스트와 유사한 구조로, logger.info를 호출하는지 확인한다. logger.info는 text를 받아 그대로 console.log하는 것으로 모킹한다.

 

[Green]

logger.middleware.ts

import { Inject, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

export class LoggerMiddleware implements NestMiddleware {
  constructor(@Inject(WINSTON_MODULE_PROVIDER) readonly logger: Logger) {}

  use(request: Request, response: Response, next: NextFunction) {
    response.on('finish', () => {
      this.logger.info('text');
      return;
    });
    next();
  }
}

logger.info를 호출하면 테스트를 통과한다.

 

[Refactor]

특별히 개선할 점은 없다.

 

logger.info를 통해 request의 정보를 로깅한다.

[Red]

logger.middleware.spec.ts

import { Test, TestingModule } from '@nestjs/testing';
import { LoggerMiddleware } from './logger.middleware';
import { Logger } from 'winston';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Request, Response, NextFunction } from 'express';
import * as http from 'http';

describe('LoggerMiddleware', () => {
  let loggerMiddleware: LoggerMiddleware;
  let logger: Logger;

  const request = {
    ip: '127.0.0.1',
    method: 'GET',
    originalUrl: '/test',
    get: jest.fn().mockImplementation((name) => {
      if (name === 'user-agent') {
        return 'user-agent';
      }
      return undefined;
    }),
  } as unknown as Request;
  const response = new http.ServerResponse(request) as unknown as Response;
  const next = jest.fn() as NextFunction;

  beforeEach(async () => {
    const module: TestingModule = await Test.createTestingModule({
      providers: [
        LoggerMiddleware,
        {
          provide: WINSTON_MODULE_PROVIDER,
          useValue: {
            info: jest.fn().mockImplementation((text) => {
              console.log(text);
            }),
          },
        },
      ],
    }).compile();

    loggerMiddleware = module.get<LoggerMiddleware>(LoggerMiddleware);
    logger = module.get<Logger>(WINSTON_MODULE_PROVIDER);
  });

  it('should be defined', () => {
    expect(loggerMiddleware).toBeDefined();
  });

  it('should call use method with request, response, next', () => {
    loggerMiddleware.use(request, response, next);

    expect(next).toHaveBeenCalled();
  });

  it('should have logger inside of middleware', () => {
    expect(loggerMiddleware).toHaveProperty('logger');
    expect(loggerMiddleware['logger']).toBe(logger);
  });

  it("should call response.on 'finish'", () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(spyResponseOn).toHaveBeenCalledWith('finish', expect.any(Function));

    spyResponseOn.mockRestore();
  });

  it('should call logger.info when finish', async () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    expect(logger.info).toHaveBeenCalled();

    spyResponseOn.mockRestore();
  });

  it('should call logger.info when finish', async () => {
    const spyResponseOn = jest.spyOn(response, 'on');

    loggerMiddleware.use(request, response, next);

    response.emit('finish');

    const expectedLogMessage = `GET /test 200 127.0.0.1 user-agent`;

    expect(logger.info).toHaveBeenCalledWith(expectedLogMessage);

    spyResponseOn.mockRestore();
  });
});

request 객체에서 사용되어질 요소들을 모킹하고 logger.info의 모킹을 만들어준다. 마지막으로 logger.info의 요소로 불려질 expectedLogMessage를 모킹한다.

 

[Green]

logger.middleware.ts

import { Inject, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

export class LoggerMiddleware implements NestMiddleware {
  constructor(@Inject(WINSTON_MODULE_PROVIDER) readonly logger: Logger) {}

  use(request: Request, response: Response, next: NextFunction): void {
    const ip = '127.0.0.1';
    const method = 'GET';
    const originalUrl = '/test';
    const userAgent = 'user-agent';
    const statusCode = 200;

    response.on('finish', () => {
      this.logger.info(
        `${method} ${originalUrl} ${statusCode} ${ip} ${userAgent}`,
      );
    });

    next();
  }
}

일단 테스트를 통과할 수 있도록 ip, method, originUrl, userAgent, statusCode를 const로 생성하여 logger.info에 넣어준다. 테스트가 통과된다.

 

[Refactor]

logger.middleware.ts

import { Inject, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

export class LoggerMiddleware implements NestMiddleware {
  constructor(@Inject(WINSTON_MODULE_PROVIDER) readonly logger: Logger) {}

  use(request: Request, response: Response, next: NextFunction): void {
    const { ip, method, originalUrl } = request;
    const userAgent = request.get('user-agent');

    response.on('finish', () => {
      const { statusCode } = response;
      this.logger.info(
        `${method} ${originalUrl} ${statusCode} ${ip} ${userAgent}`,
      );
    });

    next();
  }
}

실제 request와 response로 부터 값을 가져도록 리팩터링 한다.

 

1. LoggerMiddleware 클래스를 만든다.

2. NestMiddleware의 use 메서드를 구현한다.

3. LoggerMiddleware의 생성자로 winston logger를 주입한다.

4. use 메서드에서 response.on을 호출한다.

5. 'finish' 이벤트가 완료되면 logger의 info를 호출한다.

6. logger.info를 통해 request의 정보를 로깅한다.

 

모든 할 일 목록이 제거되고 테스트 주도로 개발된 logger.middleware가 완성되었다.

 

Reference:

nest.js middleware documentation

node.js events documentation

What is the difference between addListener(event, listener) and on(event, listener) method in node.js?