Node.js 애플리케이션에서 Request ID 추적하기

본 글은 Andrey Pechkurov의 “Request Id Tracing in Node.js Applications” 글을 번역한 것입니다.
Request Id Tracing in Node.js Applicationsarchitecture
If you ever wrote back-end applications in Node.js, you know that tracing the same HTTP request through log entries is a problem.

오역이나 부족한 개념 등은 댓글로 피드백해주시면 정말 감사하겠습니다.

만약 Node.js에서 백엔드 애플리케이션을 짜 본 적이 있다면, 같은 HTTP request를 추적하는 것이 어렵다는 것을 알 것입니다. 주로 로그들은 다음과 같이 생겼습니다:

[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:
...

로그 조각들은 흩어져 있으며 어떤 것들이 같은 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:
...

위를 보시면 [request-id:*] 부분에 request 식별자가 있습니다. 이 식별자들을 통해 같은 요청으로부터 생긴 로그들을 필터링 할 수 있습니다. 또한 애플리케이션이 HTTP로 통신하는 마이크로서비스들로 구성된 경우, request 식별자는 HTTP 헤더로 전송되어 한 체인에 있는 모든 마이크로서비스에서 생성된 로그들를 통해 request 체인을 추적할 수 있습니다. 이 기능은 모니터링 목적으로 매우 가치가 있습니다.

개발자로서 웹 프레임워크 혹은 로깅 라이브러리 설정을 한 곳에서 하고, request id를 생성하고, 자동으로 출력하고 싶을 것입니다. 하지만 불행히도, Node.js 세계에서는 약간 어렵습니다.

이 글에서는 이 문제에 대해 얘기해보고 가능한 한 가지 해결책을 살펴보고자 합니다.

좋아요, 그런데 이게 진짜 문제입니까?

JVM이나 Java Servlet 컨테이너와 같은 다른 언어와 플랫폼에서 이는 별로 문제가 되지 않습니다. 왜냐하면 HTTP 서버가 멀티 쓰레드와 블로킹 I/O 기반으로 만들어지기 때문이죠. 이 경우 HTTP request를 처리하는 쓰레드의 식별자를 로그에 넣게 된다면, 이는 자연스럽게 이미 특정 요청을 추적하기 위한 필터의 역할을 할 수 있습니다. 이 해결책이 이상적이지는 않지만, Tread-Local Storage (TLS)를 사용하면 더욱 향상 될 수 있습니다. TLS는 기본적으로 현재 쓰레드와 관련된 컨텍스트에서 키-값 쌍을 저장하고 검색하는 방법입니다. 우리의 경우, 각각의 새로운 reqest에 대해 생성 된 ID (및 다른 데이터)를 저장하는데 사용할 수 있습니다. 많은 로깅 라이브러리에는 TLS를 사용해 구축한 기능들이 있습니다.

Thread Local Storage란?

이벤트 루프를 기반으로 하는 Node.js의 비동기적 특성으로 인해 Node.js에서는 TLS와 같은 것들이 없습니다. 왜냐하면 JS 코드가 단일 쓰레드에서 처리되기 때문이죠. 만약 이런 경우 request id를 추적하고 싶다면, request를 처리하는 모든 호출에서 context 객체를 넘겨주어야 합니다.

이는 Express 애플리케이션에서 다음과 같은 형태를 띨 것입니다:

'use strict'

// a primitive logger object
const logger = {
  info: console.log
}

const express = require('express')
const uuidv4 = require('uuid/v4')

const app = express()

app.get('/', function (req, res) {
  req._id = uuidv4(); // generate and store a request id
  logger.info(`Started request handling, request id: ${req._id}`)
  
  // pass `req` object into the nested call
  fakeDbAccess(req)
    .then((result) => res.json(result))
})

async function fakeDbAccess (req) {
  return new Promise((resolve) => {
    setTimeout(() => {
      logger.info(`Logs from fakeDbAccess, request id: ${req._id}`)
      resolve({ message: 'Hello world' })
    }, 0)
  })
}

app.listen(3000, (err) => {
  if (err) {
    logger.err('The app could not start')
  }
  logger.info('The app is listening on 3000')
})

위에서 저희는 req객체를 fakeDbAccess 함수로 념겨주었고, 이로 인해 로그에 request id를 남기는 것이 가능했습니다. 이 방법은 routes와 모듈이 훨씬 많은 실제 애플리케이션에서 코드가 지저분해지고 에러가 쉽게 발생할 것입니다.

다행히도, Node.js 커뮤니티에서는 예전부터 TLS를 대체할 다른 방법들을 생각해왔고, 가장 유명한 대안은 Continuation-Local Storage (CLS) 입니다.

CLS로 구원을!

CLS의 첫 번째 구현은 continuation-local-storage 라이브러리입니다. 이는 다음과 같이 CLS를 정의합니다:

Continuous-Local Storage는 스레드 프로그래밍에서 thread-local-storage 처럼 작동하지만, 스레드 대신 노드 스타일의 콜백 체인을 기반으로 합니다.
(Continuation-local storage works like thread-local storage in threaded programming, but is based on chains of Node-style callbacks instead of threads.)

이 라이브러리의 API를 확인해본다면, Java TLS 등과 비교했을 때 훨씬 복잡하다는 것을 알 수 있습니다. 하지만 핵심 부분은 비슷합니다. context 객체를 일련의 호출 체인과 연결하여 나중에 접근할 수 있게 합니다.

초기 라이브러리는 process.addAsyncListener API를 기반으로 만들어졌습니다. 이 API는 Node.js v0.12까지 가능했고, v0.12+부터는 그에 맞는 polyfill이 있습니다. 이 polyfiil은 내장된 node API를 감싸는 것을 목표로 많은 monkey patch를 수행합니다. 이것이 최신 버전의 Node.js와 함께 이 라이브러리를 사용하면 안되는 주된 이유입니다.

polyfill이란?

다행히도 CLS 라이브러리의 후속 버전 (또는 더 정확히는 fork 버전)이 있으며 이는 cls-hooked라 불립니다. Node.js >= 8.2.1 부터는 node 내장 API인 async_hooks를 사용합니다. API가 여전히 실험적이기는 하지만, 이 선택은 polyfill을 사용하는 것보다 훨 낫습니다. Async Hooks API에 대해 더 궁금하시다면 이 포스트를 확인해주세요.

이제, 올바른 도구를 알았으니, 앱 로그에서 request id를 추적하는 방법에 접근해 볼 수 있습니다.

Express/Koa/그 외 모든 web-framework를 위한 종합 솔루션은 없을까?

Node.js 앱에서 request id를 사용하고 싶다면, cls-hooked를 사용하여 사용중인 웹 프레임워크와 통합해야 합니다. 이를 도와주는 라이브러리가 없을까요?

최근에 비슷한 라이브러리가 있는지 찾아보았지만 적합한 라이브러리를 찾지 못했습니다. 물론, Express 같은 웹 프레임워크와 CLS를 통합해주는 몇 개의 라이브러리들이 있기는 합니다. 또한 request id를 생성해주는 미들웨어 라이브러리들도 있습니다. 하지만 request id를 추척 문제 해결을 위해 두 가지를 모두 만족시키는 라이브러리는 없었습니다.

자 여러분, 이제 cls-rtracer를 만나보실 시간입니다. 작은 라이브러리이지만 작지 않은 문제를 해결해줍니다. CLS 기반 request id 생성을 구현하고 호출 체인 어디에서든 request id를 얻을 수 있는 Express 및 Koa용 미들웨어를 제공합니다.

cls-rtracer와의 통합에는 기본적으로 두 단계가 필요합니다. 첫 번째는 적합한 장소에 미들웨어를 연결하는 것입니다. 두 번째는 로깅 라이브러리 설정을 하는 것입니다.

Express 기반 앱에서는 다음과 같이 설정합니다.

'use strict'

const rTracer = require('cls-rtracer')

// that how you can configure winston logger

const { createLogger, format, transports } = require('winston')
const { combine, timestamp, printf } = format

// a custom format that outputs request id
const rTracerFormat = printf((info) => {
  const rid = rTracer.id()
  return rid
    ? `${info.timestamp} [request-id:${rid}]: ${info.message}`
    : `${info.timestamp}: ${info.message}`
})

const logger = createLogger({
  format: combine(
    timestamp(),
    rTracerFormat
  ),
  transports: [new transports.Console()]
})

// now let's configure and start the Express app

const express = require('express')

const app = express()
app.use(rTracer.expressMiddleware())

app.get('/', function (req, res) {
  logger.info('Starting request handling')
  fakeDbAccess()
    .then((result) => res.json(result))
})

async function fakeDbAccess () {
  return new Promise((resolve) => {
    setTimeout(() => {
      logger.info('Logs from fakeDbAccess')
      resolve({ message: 'Hello from cls-rtracer Express example' })
    }, 0)
  })
}

app.listen(3000, (err) => {
  if (err) {
    logger.err('The app could not start')
  }
  logger.info('The app is listening on 3000')
})

프로그램이 실행되면, 이 앱은 다음과 같은 로그를 생성합니다.

2018-12-06T10:49:41.564Z: The app is listening on 3000
2018-12-06T10:49:49.018Z [request-id:f2fe1a9e-f107-4271-9e7a-e163f87cb2a5]: Starting request handling
2018-12-06T10:49:49.020Z [request-id:f2fe1a9e-f107-4271-9e7a-e163f87cb2a5]: Logs from fakeDbAccess
2018-12-06T10:49:53.773Z [request-id:cd3a33a9-32cb-453b-a0f0-e36c65ff411e]: Starting request handling
2018-12-06T10:49:53.774Z [request-id:cd3a33a9-32cb-453b-a0f0-e36c65ff411e]: Logs from fakeDbAccess
2018-12-06T10:49:54.908Z [request-id:8b352536-d714-4838-a372-a8e2cfcb4f53]: Starting request handling
2018-12-06T10:49:54.910Z [request-id:8b352536-d714-4838-a372-a8e2cfcb4f53]: Logs from fakeDbAccess

통합 자체에는 rTracer.expressMiddleware() 함수 호출로 생성 된 Express 미들웨어를 연결하고 rTracer.id() 호출로 request id를 얻는 것이 포함됩니다. 이는 정말 간단합니다.

cls-rtracer는 request id를 추적하는 문제를 해결해주고 Node.js 앱을 진단하기 쉽게 해줍니다.

P.S. Async Hooks를 사용하는데는 특정 퍼포먼스 문제가 있습니다. 그러나 대부분의 앱에서 문제가 되지는 않습니다. 다음 댓글과 논의를 확인해보십시오.