만약 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인지 알아보기 힘들죠.
HTTP 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:*] 라고하는 식별자가 있습니다. 이 식별자를 통해 같은 사용자의 요청인지에 대한 필터링이 가능합니다.
HTTP통신을 하는 애플리케이션의 경우 한 체인에 속한 모든 마이크로서비스에서 생성된 로그를 취합할 수 있습니다.
개발자로서 추적, 로깅하고 Request Id를 생성하고 자동으로 출력하고 싶을것입니다. 하지만 불행히도 Node.js에서는 이것이 조금 힘듭니다.
이 문제를 해결하기 위한 해결책에 대해 얘기해보고자 합니다.
JVM과 Java Servlet과 같은 다양한 플랫폼과 언어에서는 이는 큰 문제가 되지 않습니다.
왜냐하면 이는 HTTP서버가 멀티쓰레드와 블로킹 I/O기반으로 만들어지기 때문입니다. 이 경우 Request Id를 추적하기 위해서는 쓰레드에 식별자를 넣게 되면
자연스럽게 HTTP Request Id의 추적이 가능합니다. 그리고 이상적이지는 않지만 TLS (Tread-Local Storage)를 통해 해결해볼 수 있습니다. TLS는 기본적으로 키-값 쌍을 이루어 저장하고 검색하는 방법입니다. 쓰레드마다 각각 생성된 Request Id를 TLS를 통해 취합할 수 있는것이죠.
하지만 Node.js는 이벤트 루프 기반의 비동기적 특성으로 인해 TLS를 사용할 수 없습니다. 왜냐하면 Java Script는 단일 쓰레기이기 때문이죠.
만약 이런경우 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를 정의합니다.
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 객체를 일련의 체인에 연결하여 나중에 접근할 수 있게 하는 것입니다.
CLS는 Node.js >= 8.2.1부터는 node 내장 API인 async_hooks를 사용합니다. API가 여전히 실험적이기는 하지만, polifill을 사용하는것 보다는 훨씬 좋습니다.
CLS를 알게 되었으니, 이제 앱 로그에서 Request Id를 추적하는 방법을 살펴보겠습니다.
여러가지 오픈코드들이 많습니다. Hello-CLS, cls-rtracer 등
예제에서는 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 fakeDbAccessrTracer.expressMiddleware()함수 호출로 생성 된 Express 미들웨어를 생성하고, 이를 rTracer.id() 호출로 Request Id를 얻고 있습니다.
정말 간단하게 HTTP Request Id를 추적할 수 있게 되었습니다.
Async Hooks는 퍼포먼스의 문제가 있습니다. Node 14 에서 이는 개선된다고 하니 Node14를 한번 더 살펴보아야 겠습니다.