로그 남기기

실제 운영중인 서비스에서 에러가 발생하는 것은 치명적이다. 그래서 평소 테스트를 통해 사전에 에러를 발견하고 코드를 검증하여 문제가 발생하지 않도록 하는 것이 중요하다.

그러나 현실에서는 언제나 예상치 못한 문제가 발생할 수 있다. 이에 대비하여 문제가 발생했을 때 빠르게 원인을 발견하고 해결하는 것도 매우 중요하다.

이러한 상황에서 도움이 되는 것이 로그이다. 따라서 로그를 효과적으로 남겨 문제를 발견하고 해결할 수 있도록 하는 것이 필요하다.

 

이번 글에서는 기존 로그의 문제점과 개선 과정에 대해 남긴다.

 

 

기존 로그의 문제점

- 로그 레벨 구분 X

error, warn, info, debug 등의 로그 레벨을 이용해서 구분하지 않고 console.log만 사용해서 로그를 남기고 있었다. 간혹 console.error를 사용하는 코드도 있었지만, 기준이 명확하지 않았다. 그래서 운영 환경에서도 개발에만 필요한 로그가 남겨지는 경우가 있었고, 로그 레벨에 대한 신뢰가 없어 로그의 성격을 파악하기 위해서는 항상 내용을 전부 읽어야 했기 때문에 비효율적이었다.

 

- 구조화 X

규격화된 로그 형식이 없어서 상황마다, 개발자마다 로그를 남기는 방식이 다 제각각이었다. 특히 에러 관련 출력 로그를 살펴보면 어떤 문제인지에 관한 문자열만 있는 경우, 에러를 그대로 출력하는 경우, 네스트가 생성한 경우 등으로 통일되지 않아서 로그를 파악하고 원하는 정보를 얻는데에 어려움이 있었다.

 

- 추적 어려움

서버가 응답할 때만 로그 출력(요청에 대한 로그x) + catch 안에서의 로그 출력(없을때도 있음) + 기준 없이 특정 상황에서만 남겨두는 로그로 인해 에러가 발생해도 로그를 통해 정보를 얻기보다는 같은 문제 상황을 재현하여 코드의 흐름을 따라가며 문제 지점을 발견하는 식으로 에러를 해결해왔었다. 그나마 이렇게 문제를 해결할 수 있다면 다행이지만, 같은 요청인데 어떤 경우에는 성공하고 어떤 경우에는 실패하는 문제가 발생할땐 문제의 원인을 발견하기가 정말 힘들었다.

 

 

개선

- 요청 로그 추가

기존에는 서버가 응답한 경우에만 로그를 남기고 있어서 로그 메세지를 볼 때 이 응답이 어떤 요청으로 인해 생겨난건지 알 수 없어 답답함이 있었는데 이번 개선 작업에서 요청이 들어왔을 때와 응답할 때 모두 로그를 남기도록 변경했다.

 

- 요청 아이디(trace ID) 적용

멀티 스레드나 비동기로 요청을 처리할 때, 서로 다른 요청끼리 로그 메세지가 섞여 있기 때문에 같은 엔드포인트로의 요청이 다수 있으면 생성된 로그 메세지가 어떤 요청으로 인해 발생한 것인지 또 응답이 어떤 요청의 응답인지 구분하기가 쉽지 않다. 그래서 요청이 들어오는 순간 요청 아이디를 생성하여 응답 로그를 포함하여 그 요청으로 인해 생성되는 모든 로그 메세지에 생성한 요청 아이디가 포함되어 출력될 수 있도록 했다.

 

- 로그 레벨 구분

error레벨의 로그들을 기준에 맞추어 warn과 error 레벨을 구분하고, 운영에 불필요한 메세지는 debug로 수정했다.

이 글을 참고하여 작업을 진행했다.

 

- 구조화

기존 로그 메세지의 출력 형식은 전부 제각각이었기 때문에 메세지의 종류와 내용을 파악하는데에 어려움이 있었다. 그래서 형식을 JSON 으로 변경하고 에러 로그일 때는 스택에 관한 정보를 포함할 수 있도록 했다. JSON 형식으로 로그를 남기면 로그를 집계하여 검색, 분석 및 모니터링에 이점이 있다. 

 

@Injectable()
export class LoggingMiddleware implements NestMiddleware {
    constructor(private readonly logger: LoggerService) {}

    use(request: Request, next: NextFunction): void {
        const { method, originalUrl } = request;
        const userAgent = request.get('user-agent') || '';
        const requestId = uuidv4();
        request['requestId'] = requestId;
        this.logger.setRequestId(requestId);

        const ip = request.headers['x-forwarded-for'] || request.ip;
        const requestLog = {
            path: originalUrl,
            method,
            ip,
            userAgent,
        };

        this.logger.info('[REQUEST]', requestLog);

        next();
    }
}

logging.middleware.ts

 

 

@Injectable()
export class LoggingInterceptor implements NestInterceptor {
    intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
        const httpContext = context.switchToHttp();
        const request = httpContext.getRequest<Request>();
        const response = httpContext.getResponse();

        const now = Date.now();
        return next.handle().pipe(
            tap(() => {
                const handlerName = context.getHandler().name;
                const responseLog = {
                    timestamp: new Date().toISOString(),
                    level: 'info',
                    requestId: request['requestId'],
                    message: '[RESPONSE]',
                    path: request.url,
                    statusCode: response.statusCode,
                    controller: handlerName,
                    processingTime: `${Date.now() - now}ms`,
                };
                console.log(JSON.stringify(responseLog));
            }),
        );
    }
}

logging.interceptor.ts

 

 

import { Injectable, Scope, Inject } from '@nestjs/common';
import { WINSTON_MODULE_PROVIDER } from 'nest-winston';
import { Logger } from 'winston';

@Injectable({ scope: Scope.REQUEST })
export class LoggerService {
    constructor(@Inject(WINSTON_MODULE_PROVIDER) private readonly logger: Logger) {}

    private childLogger: Logger;

    setRequestId(requestId: string) {
        this.childLogger = this.logger.child({ requestId });
    }

    log(message: any, ...meta: any[]) {
        this.info(message, ...meta);
    }

    info(message: any, ...meta: any[]) {
        if (typeof message === 'object' && meta.length === 0) {
            return this.childLogger.info(message);
        }

        if (meta.length > 0 && typeof meta[meta.length - 1] === 'function') {
            const callback = meta.pop();
            return this.childLogger.info(message, ...meta, callback);
        }

        if (meta.length > 0 && typeof meta[0] === 'string') {
            message += meta[0];
            meta = meta.slice(1);
        }

        return this.childLogger.info(message, ...meta);
    }
    
}

logger.service.ts

 

 

미들웨어에서 요청 로그를 남기고 인터셉터에서 응답 로그를 남기고 있다.

하나의 인터셉터에서 요청 로그와 응답 로그를 같이 관리하고 싶었지만 네스트의 Request lifecycle 을 보면 요청이 인터셉터 이전에 가드를 먼저 통과하기 때문에 미들웨어에서 요청 로그를 남긴다.

참고: https://docs.nestjs.com/faq/request-lifecycle#summary

 

 

 

참조

https://betterstack.com/community/guides/logging/logging-best-practices/

https://bcho.tistory.com/1319

---

남은 작업

- 분산 시스템에서의 컨텍스트 연결

- 로그 집계 및 알람 구축 다음글

 

 

+ 추가

다른 서버와 로그 연결

MSA 환경에서의 요청 트랜잭션을 추적할 수 있도록 도와주는 Jaeger와 Zipkin 같은 여러 도구들이 있지만 현재 상황에서는 이 도구들이 제공하는 추가적인 기능을 이용할 계획이 없고, 툴을 사용하기 위한 러닝커브도 존재하기 때문에 간단하게 HTTP 헤더를 이용해 요청 ID를 넘겨주기로 했다.

 

1. 미들웨어 요청 ID 할당 부분 수정

let requestId;
if (request.headers['x-correlation-id']) {
	requestId = request.headers['x-correlation-id'];
}

logging.middleware.ts

 

 

2. 분산 시스템 서버로의 요청 헤더에 X-Correlation-ID 설정

 

 

이렇게 하면 서비스 전반에 걸쳐 요청을 추적할 수 있다.