NestJS에 winston으로 로그 남기기

Winston Logger

Winston의 Logging 레벨은 RFC5424 표준을 따르고 있다고 한다.

RFC 5424: The Syslog Protocol

Numerical         Severity
 Code

  0       Emergency: system is unusable
  1       Alert: action must be taken immediately
  2       Critical: critical conditions
  3       Error: error conditions
  4       Warning: warning conditions
  5       Notice: normal but significant condition
  6       Informational: informational messages
  7       Debug: debug-level messages

 

winston logger level

const levels = {
  error: 0,
  warn: 1,
  info: 2,
  http: 3,
  verbose: 4,
  debug: 5,
  silly: 6
};

winston logger를 생성할 때

level 옵션을 주게 되면 주어진 옵션보다 작거나 같은 레벨만 출력된다.

const logger = winston.createLogger({
  level: 'info',
  transports: [
    new winston.transports.Console(),
  ]
});

 

예를 들어 위와같이 info 레벨을 주게되면, error, warn, info만 출력되게 된다.

로그 파일로 남기기

winston으로 로그를 남길 때 어디에 로그를 출력할 지 설정할 수 있다.

transports 옵션으로 출력을 설정할 수 있다.

위의 예시 처럼 남기게되면 콘솔에만 찍히고 어디에도 남아있게 되지 않는다.

const logger = winston.createLogger({
  transports: [
    new winston.transports.File({
      filename: 'combined.log',
      level: 'info'
    }),
  ]
});

이렇게 설정하게 되면 파일로 저장할 수 있다.

하지만 위와 같이 설정하게 되면 모든 로그가 한 파일에 담길 수 있다.

 

로그를 날짜, 시간별로 관리하기 위해서 winston-daily-rotate-file을 도입했다.

로그를 순환할 수 있고, 개수, 경과일 수를 기준으로 오래된 로그를 삭제할 수있게 도와주는 패키지이다.

const transport: winston.transport[] = [
      new winstonDaily({
        filename: '%DATE%.log',
        datePattern: 'YYYY-MM-DD-HH',
        dirname: logDir,
        zippedArchive: true,
        maxSize: '20m',
        maxFiles: '7d',
      }),
    ];

각종 옵션들로 로그파일의 최대 사이즈, 몇 일간의 로그를 저장할지, 어떤 패턴으로 저장할 지 등을 지정할 수 있다.

NestJS에 도입하기

NestJs에서는 기본적으로 Logger를 제공하고 있고, 싱글톤 패턴으로 관리한다.

Winston을 NestJS 생명주기에 적합하게 도입하기 위해서 Winston으로 LoggerService의 구현체를 만들어 주입해서 이용해야한다.

LoggerService 인터페이스는 다음과 같이 구현되어있었다.

export interface LoggerService {
    /**
     * Write a 'log' level log.
     */
    log(message: any, ...optionalParams: any[]): any;
    /**
     * Write an 'error' level log.
     */
    error(message: any, ...optionalParams: any[]): any;
    /**
     * Write a 'warn' level log.
     */
    warn(message: any, ...optionalParams: any[]): any;
    /**
     * Write a 'debug' level log.
     */
    debug?(message: any, ...optionalParams: any[]): any;
    /**
     * Write a 'verbose' level log.
     */
    verbose?(message: any, ...optionalParams: any[]): any;
    /**
     * Write a 'fatal' level log.
     */
    fatal?(message: any, ...optionalParams: any[]): any;
    /**
     * Set log levels.
     * @param levels log levels
     */
    setLogLevels?(levels: LogLevel[]): any;
}

로깅 레벨이 Winston과 살짝 다른 것을 발견할 수 있었다.

NestJS는 Logging Level을 지정하는 것이 아니라 출력하고 싶은 레벨을 배열로 설정하는 형태인 것을 알 수 있었다.

const app = await NestFactory.create(AppModule, {
  logger: ['error', 'warn'],
});
await app.listen(3000);

 

Winston과 NestJS은 서로 다른 로그 시스템을 가지고 있어,

NestJS에서 Winston을 이용하기위해 인터페이스에서 제공하는 것과 Winston에서 일치하는 로그레벨만 사용했다.

Winston에서 제공하는 로그레벨의 순서를 알아냈어야 했다.

// winstonLogger.service.ts
// LoggerService 구현체

log(message: string, ...optionalParams: any[]) {
  this.logger.log(message, ...optionalParams);
}

error(message: string, ...optionalParams: any[]) {
  this.logger.error(message, ...optionalParams);
}

warn(message: string, ...optionalParams: any[]) {
  this.logger.warn(message, ...optionalParams);
}
debug(message: string, ...optionalParams: any[]) {
  return this.logger.debug(message, ...optionalParams);
}
verbose(message: string, ...optionalParams: any[]) {
  this.logger.verbose(message, ...optionalParams);
}

@Controller()
export class AppController {
  private readonly logger = new Logger();

  constructor(private readonly appService: AppService) {}

  @Get()
  getHello(): string {
    this.logger.log('log level');
    this.logger.error('error level');
    this.logger.warn('warn level');
    this.logger.debug('debug level');
    this.logger.verbose('verbose level');

    return this.appService.getHello();
  }
}

위와 같이 테스트용 컨트롤러를 구성하고, winson 출력로그 레벨을 바꾸면서 테스트했다.

레벨별 출력 결과

debug

verbose

info

warn

error

 

우선순위는

error → warn → info → verbose → debug 순서임을 알 수 있었고

NestJS의 log가 Winston의 info에 해당한다는 것도 알 수 있었다.

 

운영하는 서버에서 로그 확인하기

winston, winston-daily-rotate-file, NestJS LoggerService를 이용해서 서버 로그를 남길 수 있게되었고

서버에서 로그파일을 확인할 수 있었다.

그런데 한 가지 문제가 있었다.

도커로 서버를 띄워서 운영하고 있었기 때문에, 재배포가 일어나면 도커컨테이너가 변경되어 쌓아온 로그파일이 날라가 버렸다.

개발 중 서버가 한 번 죽은 적이 있었는데, 이전 로그가 다 날아가버려서 이유를 찾을 수 없었다.

도커 볼륨 마운트

이를 해결하기 위해서 서버의 볼륨과 도커 컨테이너의 볼륨을 마운트해서 로그파일이 계속 유지되도록 했다.

version: '3.8'

services:
  blue:
    container_name: blue
    image: hkleeeee/api
    ports:
      - 4001:4000
    env_file:
      - .env
    volumes:
      - ./logs:/var/app/logs
    restart:
      always
  green:
    container_name: green
    image: hkleeeee/api
    ports:
      - 4002:4000
    env_file:
      - .env
    volumes:
      - ./logs:/var/app/logs
    restart:
      always

도커 컴포즈 파일에 volumes을 연결해주었다.

이 옵션을 통해 도커 재시작에도 로그 파일을 유지할 수 있게 되었고,

로그를 확인하는 것도 더 편해졌다.

전에는 서버 ssh 접속 → 도커 인터렉티브 모드로 접속 → 로그파일 위치로 이동 과정을 통해 로그파일을 확인할 수 있었는데,

볼륨 마운트를 통해서 도커에 접속하지 않고도 로그 파일을 확인할 수 있었다.

에러 레벨의 로그 별도로 모으기

모든 로그를 한 파일에 작성하면서 서버를 운영하고 있었다.

그리고 부하테스트를 진행했는데 이 부분에 불편함이 생겼다.

무수히 많은 요청 속에서 에러가 발생하는 곳의 로그를 보고 싶었는데, 모든 레벨의 로그를 한 파일에 담고 있으니 에러 로그를 찾기가 너무 어려웠다.

그래서 에러레벨의 로그만 별도로 저장하는 설정을 추가해주었다.

const transport: winston.transport[] = [
      new winstonDaily({
        filename: '%DATE%.log',
        datePattern: 'YYYY-MM-DD-HH',
        dirname: logDir,
        zippedArchive: true,
        maxSize: '20m',
        maxFiles: '7d',
      }),
      new winstonDaily({
        filename: '%DATE%.error.log',
        datePattern: 'YYYY-MM-DD-HH',
        dirname: logDir + '/error',
        zippedArchive: true,
        maxSize: '20m',
        maxFiles: '7d',
        level: 'error',
      }),
    ];

첫번째 transport는 모든 로그를 순서대로 보여주어 로그의 흐름을 알 수 있다.

두번째 transport는 출력되는 로그중 에러레벨만 따로 저장하고 있어 에러가 발생한 경우만 따로 찾아볼 수 있게되었다.

---

완성한 코드

//winstonLogger.service.ts
import { utilities, WinstonModule } from 'nest-winston';
import * as winstonDaily from 'winston-daily-rotate-file';
import * as winston from 'winston';
import * as path from 'path';

const { combine, timestamp, printf, colorize } = winston.format;
import { Injectable, LoggerService } from '@nestjs/common';
import { ConfigService } from '@nestjs/config';

@Injectable()
export class WinstonLogger implements LoggerService {
  private logger: LoggerService;
  private readonly logDir = (() => {
    const __dirname = path.resolve();
    return path.join(__dirname, 'logs');
  })();

  constructor(private configService: ConfigService) {
    const transport = this.getTransport();
    this.logger = this.createLogger(transport);
  }

  getTransport(): winston.transport[] {
    const transport: winston.transport[] = [
      new winstonDaily({
        filename: '%DATE%.log',
        datePattern: 'YYYY-MM-DD-HH',
        dirname: this.logDir,
        zippedArchive: true,
        maxSize: '20m',
        maxFiles: '7d',
      }),
      new winstonDaily({
        filename: '%DATE%.error.log',
        datePattern: 'YYYY-MM-DD-HH',
        dirname: this.logDir + '/error',
        zippedArchive: true,
        maxSize: '20m',
        maxFiles: '7d',
        level: 'error',
      }),
    ];

    if (this.configService.get<string>('NODE_ENV') !== 'production') {
      const devConsole = new winston.transports.Console({
        format: combine(
          colorize(),
          utilities.format.nestLike('API Server', {
            prettyPrint: true,
          }),
        ),
      });

      transport.push(devConsole);
    }
    return transport;
  }

  createLogger(transport: winston.transport[]) {
    const logFormat = printf(
      ({ level, message, timestamp }) => `${timestamp} ${level}: ${message}`,
    );
    return WinstonModule.createLogger({
      format: combine(
        timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
        logFormat,
      ),
      level:
        this.configService.get<string>('NODE_ENV') !== 'production'
          ? 'debug'
          : 'info',
      transports: transport,
    });
  }

  log(message: string, ...optionalParams: any[]) {
    this.logger.log(message, ...optionalParams);
  }

  error(message: string, ...optionalParams: any[]) {
    this.logger.error(message, ...optionalParams);
  }

  warn(message: string, ...optionalParams: any[]) {
    this.logger.warn(message, ...optionalParams);
  }
  debug(message: string, ...optionalParams: any[]) {
    return this.logger.debug(message, ...optionalParams);
  }
  verbose(message: string, ...optionalParams: any[]) {
    this.logger.verbose(message, ...optionalParams);
  }
}