[MSA, Logging] Nodejs 애플리케이션에서 request ID를 correlation ID로 사용하는 법

Background

MSA에 대한 로깅과 모니터링은 큰 고민거리이다. 서로 다른 개별 마이크로서비스에서 발생하는 로그를 연결 지어 트랜잭션의 처음부터 끝까지 순서대로 추적해 내는 것은 매우 어렵다.

 

MSA 환경에서 '의미 있는 로깅' 시스템을 구축하려면 어떻게 해야할까?

여기서 '의미 있는 로깅'이란 개발자뿐만 아니라 우리 서비스를 사용하는 관리자나, 사내 비개발직군의 다른 팀원들(가령 우리 서비스의 사용율과 에러율, 비용이 비싼 AI 분석 요청의 횟수.. 등의 데이터 분석이 필요한 사업개발팀) 모두가 쉽게 찾아볼 수 있고, 수집되고 가공시킨 로그 데이터를 이해하기 쉬운 로그를 말한다. 

 

What do you need to build a meaningful logging system in MSA?

Note: A good/meaningful logging system is a system that everyone can use and understand. Don’t think that only developers need logging.

 

이러한 문제점을 해결하기 위해선 로그 데이터를 인덱싱 하고, 검색할 수 있는 중앙 수집 지점을 만들어 전체 서비스 인스턴스의 모든 로그를 실시간 스트리밍하는 것이 필요하다고 많은 글들과 세션 들에서 말한다. 

 

백엔드에서 의미 있는 로깅 시스템을 구축하기 위해 MSA 환경에서는 몇 가지 고려해야 할 사항들이 있고, 그 중 하나는 correlation ID이다. 

이 글에서는 회사에서 Node.js Express application인 Api server의 logging에서 한 request로 발생한 로그마다 request ID를 correlation ID로 사용하고자 cls-rtracer를 통해 개발한 경험을 정리하고자 한다. 

많은 부분 Request Id Tracing in Node.js Applications 글을 참고하였으며 해당 글의 예시를 가져온 부분은 주석 박스에 넣었다. 

 

Request ID

correlation ID로 Request ID를 사용하려고 하는데, correlation ID는 각 요청을 식별하기 위한 식별자로 사용된다. 로그 조각들이 흩어져 있고 어떤 것이 같은 요청으로부터 발생한 것인지 알 수 없을 때, correlation ID를 사용하면 어떤 요청과 연관된 로그인지 파악할 수 있다. 또한 MSA에서는 각 마이크로서비스 간에 HTTP로 통신하는 경우 request 식별자를 HTTP 헤더로 전송하여 요청 체인을 추적할 수 있다.

 

correlation ID가 없는 기본적인 로그의 형태는 아래와 비슷할 것이다. 

[07/Nov/2018:15:48:11 +0000] User sign-up: starting request validation
[07/Nov/2018:15:48:11 +0000] User sign-up: starting request validation
[07/Nov/2018:15:48:12 +0000] User sign-up: request validation success
[07/Nov/2018:15:48:13 +0000] User sign-up: request validation failed. Reason:

 

그런데 앞서 correlation ID에 대해서 잠깐 적은 것처럼 이런 로그가 무지성으로 그냥 나열만 된다면 어떤 request에서 이 로그가 발생한 것인지 추적하기가 어렵다. 더욱이 내가 로깅 시스템을 개발해야 하는 서버의 아키텍처는 

• MSA이고 
• Api server만 하더라도 3 layer architecture로 되어있어서, controller, service, model(repository) layer에서 각각 로그가 발생하기 때문에 

 

더욱이 correlation ID로 로그마다 어떤 request로 인해 발생한 것인지 적혀있어야 연결 지을 수 있다. 

 

즉, [request-id:550e8400-e29b-41d4-a716-446655440000]  이렇게 request 식별자가 포함된 아래와 같은 로그 형식이 필요하다. 

[07/Nov/2018:15:48:11 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: starting request validation
[07/Nov/2018:15:48:11 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: starting request validation
[07/Nov/2018:15:48:12 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: request validation success
[07/Nov/2018:15:48:13 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: request validation failed. Reason: ...

 

보통 Express 애플리케이션에서 로깅을 위해 Winson을 써서 아래와 같이 구현이 되어있을 것이다. 

import { createLogger, transports, format } from 'winston';

class WinstonLogger {
  private logger: any;

  constructor() {  
    const option: winston.LoggerOptions = {
        levels: winston.config.npm.levels,
        level: process.env.NODE_ENV === 'development' || 'test' ? 'debug' : 'info',
        format: winston.format.combine(
            winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
            winston.format.metadata(),
            winston.format.errors({ stack: true }),
            winston.format.splat(),
            winston.format.json(),
        ),
        transports: [new transports.Console()]
    };
    this.logger = winston.createLogger(option);
  }

  public info(message: string): void {
    this.logger.info(message);
  }

  public warn(message: string): void {
    this.logger.warn(message);
  }

  public error(message: string): void {
    this.logger.error(message);
  }
}

// 사용 예제
const logger = new WinstonLogger();
logger.info('이것은 정보 로그입니다.');
logger.warn('주의해야 할 사항이 있습니다.');
logger.error('에러가 발생했습니다.');

그리고 Dependency Injection과 3 layer architecture을 사용하는 경우 한 파일에서 logger를 생성해주고 이를 주입해 주는 방식으로 구현이 되어있을 것이다. 

 

그러면 correlation ID로 사용할 request ID 생성을 위한 설정도 위 WinstonLogger class에서만 해주고, 모든 로그에서 알아서 출력되는 것이 좋을 것이다. 그렇지 않으면  contoller에서 request를 받으면 그에 대한 request ID를 uuid로 생성해 주고,

req._id = uuidv4(); // generate and store a request id

그 아래 호출되는 모든 함수와 모든 로그마다 그 request ID를 전달해 주고, logger에서도 이를 매번 다 적어줘야 하기 때문에 이 방법은 routes와 모듈이 훨씬 많은 실제 애플리케이션에서 코드가 지저분해지고 실수가 발생할 가능성도 크다. 

logger.info(`Started request handling, request id: ${req._id}`)

 

 

Nodejs에서 request ID 사용

HTTP 서버가 멀티 스레드와 블로킹 I/O 기반인 경우는 한 요청이 한 thread를 소비해서 블로킹으로 그게 끝날 때까지 얘가 계속 담당하게 되면 각각의 요청을 고유하게 식별하기 위해 thread 식별자를 request ID로 사용하면 이는 자연스럽게 이미 특정 요청을 추적하기 위한 필터의 역할을 할 수 있다. (JVM이나 Java Servlet 컨테이너의 경우가 그렇다고 한다.)

 

하지만 Nodejs는 싱글 쓰레드 이벤트 루프를 사용하는 비동기, 논 블로킹 I/O 모델을 기반으로 한 JavaScript 런타임이다. 다시 말해 Nodejs에서는 새로운 요청이 올 때마다 이벤트 루프가 해당 요청을 비동기 식으로 처리한다. 따라서 Node.js에서는 각각의 요청을 고유하게 식별하기 위해 thread 식별자를 request ID로 사용하는 것이 어렵다. 

이건 다른 얘기인데, 사내에서는 api server로 Nodejs Express도 사용하긴 하지만 다른 서비스는 Python Flask를 사용한다.

HTTP 서버가 싱글 스레드와 블로킹 I/O 기반인 Flask의 경우는 각각의 요청은 별도의 스레드에서 처리되지 않는다. 싱글 스레드 기반의 웹 프레임워크이기 때문에 모든 요청이 같은 스레드에서 처리된다. 따라서 단일 스레드에서 동작하기 때문에 모든 요청이 같은 스레드 ID를 가지게 된다. 이 경우 역시 thread 식별자를 request ID로 사용할 수 없다. 그래서 Flask의 경우 Flask-Correlation-Id는 요청마다 고유한 식별자를 생성하여 요청을 추적할 수 있게 한다고 한다. 
이에 대한 방식은 Adding Request IDs to FlaskAdding Request IDs to Flask 와 flask-log-request-id을 참고할 수 있다. 
 

 

TLS와 CLS

멀티 JVM이나 Java Servlet와 같이 스레드와 블로킹 I/O 기반인 경우 thread 식별자를 request ID로 사용하여 로깅 시스템을 구축하는 경우 각 스레드에 대한 고유한 저장 공간을 제공하는 Tread-Local Storage (TLS)을 사용해서 이를 효과적으로 할 수 있다. 

JVM 개발 경험이 부재하여 간단히 알아본 바에 의하면 아래와 같은 방식으로 TLS를 사용할 수 있다고 한다.

1. 요청이 들어오면 서블릿 컨테이너는 요청을 처리하기 위해 새로운 스레드를 생성합니다.
2. 새로운 스레드에서 요청 ID를 생성하고, 이를 TLS에 저장합니다.
3. 이후 해당 스레드에서 실행되는 모든 코드에서는 TLS를 통해 요청 ID에 접근할 수 있습니다.
4. 요청이 완료되면 해당 요청의 스레드에서 TLS에 저장된 요청 ID를 삭제합니다.

TLS를 사용하면 각각의 스레드에서 자신만의 요청 ID를 유지할 수 있으므로, 로그 또는 기타 추적 목적으로 사용할 수 있습니다. 예를 들어, 요청 ID는 로그 메시지에 포함되거나 헤더에 추가되어 추적 용도로 사용될 수 있습니다.

from chatGPT

 

반면 위에서 알아본 바와 같이 thread 식별자를 request ID로 사용하는 것이 의미 없는 Nodejs 애플리케이션의 경우 TLS를 대체할 다른 방법으로 Continuation-Local Storage (CLS)를 제시한다. TLS가 각 thread의 일관된 상태 저장을 위해 사용하는 것처럼 CLS도 비슷하지만 다르게 thread 대신 callback chain을 기반으로 비동기 작업이나 이벤트 핸들러가 다른 스레드에서 실행될 때도 일관된 상태를 유지할 수 있도록 한다. Node.js에서는 cls-hooked 모듈을 사용하여 CLS를 구현할 수 있다. 

CLS는 다음과 같은 메커니즘을 사용하여 구현될 수 있다. 

1. 콘텍스트 저장소(Context Storage): 각각의 비동기 작업에 대한 컨텍스트를 저장하고 관리하는 저장소입니다. 컨텍스트는 키-값 쌍으로 구성되며, 해당 비동기 작업에서 필요한 상태나 데이터를 저장합니다.
2. 컨텍스트 전파(Context Propagation): 비동기 작업이 생성될 때 컨텍스트를 전파하여 하위 작업이 부모 작업의 컨텍스트를 상속받을 수 있도록 합니다. 이를 통해 컨텍스트가 여러 작업 간에 전달되어 일관된 상태 유지가 가능해집니다.
3. 컨텍스트 액세스(Context Access): 컨텍스트에 저장된 데이터에 접근하는 방법을 제공합니다. 각 비동기 작업은 자신의 컨텍스트에 액세스하여 필요한 데이터를 읽거나 쓸 수 있습니다.

from chatGPT

 

cls-rtracer

다시 정리하면 Node.js application에서 request ID를 사용하고 싶다면, 사용 중인 웹 프레임워크에서 cls-hooked를 사용해야 한다. 

이를 간단하게 지원해 주는 라이브러리가 cls-rtracer이다. 

 

Request Tracer - Express & Koa middlewares and Fastify & Hapi plugins for CLS-based request id generation, batteries included. An out-of-the-box solution for adding request ids into your logs.

from https://github.com/puzpuzpuz/cls-rtracer 

 

아래는 Express api 애플리케이션의 winstonLogger class에 cls-rtracer를 적용한 순서를 간단한 예시 코드로 대체하여 소개하고자 한다. 

1. Install

npm install --save cls-rtracer

2. Middleware 연결

rTracer.expressMiddleware() 함수 호출로 생성된 Express 미들웨어를 연결한다. 

import express from 'express';
import * as rTracer from 'cls-rtracer';

const app = express()
// any third party middleware that does not need access to request ids goes here
// ...

app.use(rTracer.expressMiddleware())

expressMiddleware의 option을 활용해서 원하는 request ID를 생성할 수도 있다. 

예를 들어, request ID로 고유한 uuid와 user의 계정 정보를 함께 넣고 싶다면 아래와 같이 구현할 수 있다. 

export const requestTracerMiddleware = async (getUuidFromToken: (req: Request) => TokenPayload) => {
    const requestIdFactory = (req: Request): RequestIdentifyData => {
        const tokenPayload = req.headers['authorization'] ? getUuidFromToken(req) : 'N/A';
        let userInfo: string = // userInfo를 얻는 로직 구현
        return {
            requestId: uuidv4(),
            userInfo,
        };
    };
    return rTracer.expressMiddleware({ requestIdFactory });
};

app.use(await requestTracerMiddleware(ddxGetUuidFromToken));

3. logger와 연결

위의 미들웨어에서 request ID를 생성해 주었다면 logger에 request ID를 포함하는 형식으로 로그 메시지를 출력해야 한다. 

winston의 경우

import { createLogger, transports, format } from 'winston';

class WinstonLogger {
  private logger: any;

  constructor() {
  	// HERE!
    const rTracerFormat = printf((info) => {
      const rid = rTracer.id()
      return rid
        ? `${info.timestamp} [request-id:${rid}]: ${info.message}`
        : `${info.timestamp}: ${info.message}`
    })
    
    const option: winston.LoggerOptions = {
        levels: winston.config.npm.levels,
        level: process.env.NODE_ENV === 'development' || 'test' ? 'debug' : 'info',
        format: winston.format.combine(
            winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
            winston.format.metadata(),
            winston.format.errors({ stack: true }),
            winston.format.splat(),
            winston.format.json(),
            // HERE!
            rTracerFormat
        ),
        transports: [new transports.Console()]
    };
    this.logger = winston.createLogger(option);
  }

  public info(message: string): void {
    this.logger.info(message);
  }

  public warn(message: string): void {
    this.logger.warn(message);
  }

  public error(message: string): void {
    this.logger.error(message);
  }
}

// 사용 예제
const logger = new WinstonLogger();
logger.info('이것은 정보 로그입니다.');
logger.warn('주의해야 할 사항이 있습니다.');
logger.error('에러가 발생했습니다.');

 

여기까지 마무리되고 application을 실행하면 이 글의 시작에서 소개했던

[07/Nov/2018:15:48:11 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: starting request validation
[07/Nov/2018:15:48:11 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: starting request validation
[07/Nov/2018:15:48:12 +0000] [request-id:550e8400-e29b-41d4-a716-446655440000] User sign-up: request validation success
[07/Nov/2018:15:48:13 +0000] [request-id:340b4357-c11d-31d4-b439-329584783999] User sign-up: request validation failed. Reason: ...

이런 식으로  로그에 request ID가 포함되어 출력된다. 이를 통해 각 로그와 해당하는 request을 연결할 수 있다.

 

더 나아가

이 외에도 logging system을 구현하면서 고려하고 답을 찾고자 공부한 아래 주제들이 있다. 

• Logging approaches in MSA: Logging in each service vs Central Logging service Pros and Cons
• Log record attribute: Central Logging service 에서 고려할 것과 log 에 들어가야 할 정보들 
• Logging backup/restore policy:
  • log 저장 공간 threshold를 정하는 것과 이 threshold에 임박했을 때 대응방법
  • logging server에 문제가 생겼을 때 backup/restore 방법
• Docker를 사용하는 API server에서 Elasticsearch와 Logstash로 log 시각화 및 query api 만들기

 

이 각각에 대해서 시간 나는 대로 블로그에 정리해보고자 한다. 

 

도움 받은 글

• https://github.com/puzpuzpuz/cls-rtracer
• Request Id Tracing in Node.js Applications
• Node.js 애플리케이션에서 Request ID 추적하기