이 글은 Guillaume Bession의 개인 블로그에 올라와있는 Getting per-request context in NodeJS with async_hooks 글의 번역글입니다.
저는 최근 NodeJS로 HTTP 서버를 개발하던 도중 문제를 맞닥트리게 되었습니다. 저는 제 코드베이스의 많은 부분에서 로깅을 하고 있었고, 각 요청별로 유니크ID를 가졌습니다. 저는 이 유니크한 ID를 각 요청 안에서 무슨 일이 일어나고 있는지 추적하기 위해 로그 메시지에 붙이고 싶었습니다. 이걸 어떻게 하면 효율적으로 할 수 있을까요?
자아 간단한 방법은 모든 함수에 이 요청 ID를 넘겨 처리하는 방법입니다. 하지만 이런 방식으로 문제를 해결하면 코드가 유지보수하기 쉽지 않다는 문제가 발생합니다: 만약 제가 함수 안에서 함수를 호출하는 식으로 5개 스택의 함수를 호출하게 되면, 저는 여기에 해당하는 모든 함수 인자로 이 ID를 받는 부분을 추가해야만 합니다.
"context" 객체를 모든 함수에 넘겨 처리하는 방법도 있겠지만 여전히 문제는 존재합니다. 오래 걸리는 쿼리가 감지되었을 때 함수를 실행할 수 있게 해주는 SQL 라이브러리를 사용하는데 이 함수는 오직 query string만 받아 사용할 수 있습니다. 제가 원하는 요청 context는 넘길 수 없죠.
만약 당신이 실험적인 NodeJS 기능을 사용하는 데 충분한 준비가 되었다면, 저는 이 글에서 async_hooks라는 매우 훌륭한 해결책을 소개하고 싶습니다.
async_hooks에 관한 몇가지 이론
async_hooks 모듈은 비동기 리소스를 추적할 수 있는 함수를 제공합니다. 이 훅은 setTimeout, 서버 리스너 또는 다른 비동기 작업이 만들어지거나 시작되거나 끝나거나 제거될 때 호출됩니다.
비동기 리소스가 생성될 때, 새로운 asyncId가 해당 비동기 리소스에 할당되게 되고, 우리의 init 훅이 이 id와 부모 리소스의 asyncId를 넘겨받아 실행됩니다. 또한 이 모듈은 현재 실행되고 있는 함수의 asyncId 를 반환하는 executeAsyncId() 라는 매우 유용한 메소드를 제공합니다.
여기에 어떻게 우리가 훅이 실행될 때 메시지를 로깅했는지 확인할 수 있습니다:
const fs = require('fs');
const async_hooks = require('async_hooks');
const log = (str) => fs.writeSync(1, `${str}\n`);
async_hooks.createHook({
init(asyncId, type, triggerAsyncId) {
log(`INIT: asyncId: ${asyncId} / type: ${type} / trigger: ${triggerAsyncId}`);
},
destroy(asyncId) {
log(`DESTROY: asyncId: ${asyncId}`);
},
}).enable();이 코드에서console.log를 사용하지 않았다는 것을 확인할 수 있을텐데, 이는console.log는 비동기 작업이고, 이가 의미하는 것은console.log가 실행될 때 비동기 훅이 또(무한정으로) 실행된다는 사실입니다. 이곳에서의 해결책은 동기 함수인fs.writeSync를 이용하고 우리가 만든 훅을 트리거하지 않는 것입니다.
간단하게 setTimeout 을 활용한 훅을 이용해 확인해봅시다:
log(`>> Calling setTimeout: asyncId: ${async_hooks.executionAsyncId()}`);
setTimeout(() => {
log(`>> Inside setTimeout callback: asyncId: ${async_hooks.executionAsyncId()}`);
}, 0);
log(`>> Called setTimeout: asyncId: ${async_hooks.executionAsyncId()}`);위 코드를 실행하면 다음과 같은 결과를 확인할 수 있습니다:
>> Calling setTimeout: asyncId: 1
INIT: asyncId: 2 / type: Timeout / trigger: 1
>> Called setTimeout: asyncId: 1
>> Inside setTimeout callback: asyncId: 2
DESTROY: asyncId: 2어떤 일이 일어났는지 확인해봅시다:
- asyncId 1로 시작했고 setTimeout을 호출했습니다.
Timeout이라는 비동기 리소스가 생성됐고 우리가 만든init훅이 새로 생성된 asyncId 2와 부모 asyncId 1을 받아 실행됐습니다.- 프로그램 끝에 남긴 로그에서 asyncId는 여전히 1로 확인됩니다.
Timeout리소스 콜백이 호출됐고 asyncId 2가 기록되었습니다.- `Timeout` 리소스가 제거됐고 우리가 만든
destroy훅이 실행됐습니다.
이외에도 before 과 after 라는 훅이 존재합니다. 이 훅들은 외부 HTTP 요청 또는 SQL 쿼리와 같은 비동기 리소스에서 시간을 재는 데 사용될 수 있습니다.
알겠는데, 그래서 요점은요?
executionAsyncId() 와 init 와 함께 (비동기라 더라도)우리가 만든 함수의 스택을 다시 만들 수 있습니다.
여기에 와닿는 실제 예제가 있습니다. 우리는 HTTP 서버를 만들 거고, 이 서버는 각 요청마다 test.txt 파일의 내용을 읽고 보내는 서버입니다.
const fs = require('fs');
const async_hooks = require('async_hooks');
const http = require('http');
const log = (str) => fs.writeSync(1, `${str}\n`);
async_hooks.createHook({
init(asyncId, type, triggerAsyncId) {
log(`asyncId: ${asyncId} / trigger: ${triggerAsyncId}`);
},
}).enable();
const readAndSendFile = (res) => {
fs.readFile('./test.txt', (err, file) => {
log(`>> Inside readAndSendFile: execution: ${async_hooks.executionAsyncId()}`);
res.end(file);
});
}
const requestHandler = (req, res) => {
log(`>> Inside request: execution: ${async_hooks.executionAsyncId()}`);
readAndSendFile(res);
}
const server = http.createServer(requestHandler);
server.listen(8080);이 코드를 실행하고 두 개의 요청을 보내봅시다. 결과에서 불필요한 부분은 지웠습니다.
>> Inside request: execution: 6
asyncId: 9 / trigger: 6
asyncId: 11 / trigger: 9
asyncId: 12 / trigger: 11
asyncId: 13 / trigger: 12
>> Inside readAndSendFile: execution: 13
[...]
>> Inside request: execution: 31
asyncId: 34 / trigger: 31
asyncId: 36 / trigger: 34
asyncId: 37 / trigger: 36
asyncId: 38 / trigger: 37
>> Inside readAndSendFile: execution: 38두 요청에 두 개의 asyncId (6, 31)가 할당된 것을 확인할 수 있습니다. 파일을 읽는 건 새로운 비동기 리소스를 만들고, readAndSendFile 은 두 개의 asyncId (13, 38)이 기록되었습니다.
readAndSendFile 함수에서 "async path"를 추적하여 원래 요청의 asyncId 를 확인할 수 있는데, 예를 들어 첫번째 요청의 asyncId는 13이었고 이를 역추적하여 13 -> 12 -> 11 -> 9 -> 6을 얻을 수 있습니다.
쓸만한 것으로 만들기
위 모든 것들을 이용해 각 요청마다 context 객체를 만들고 가져오는 함수를 만들 수 있습니다. 이는 HTTP 서버 뿐 아니라 다른 곳에서도 사용될 수 있겠죠.
const async_hooks = require('async_hooks');
const contexts = {};
async_hooks.createHook({
init: (asyncId, type, triggerAsyncId) => {
// 새로운 비동기 리소스가 생성되었을 때
// 만약 부모 asyncId가 이미 context 객체를 가지고 있다면
// 해당 context 객체를 현재 리소스 asyncId에 할당합니다
if (contexts[triggerAsyncId]) {
contexts[asyncId] = contexts[triggerAsyncId];
}
},
destroy: (asyncId) => {
// 메모리 누수를 방지하기 위해 정리하는 작업을 합니다
delete contexts[asyncId];
},
}).enable();
function initContext(fn) {
// 새로운 비동기 리소스의 초기화를 강제합니다
const asyncResource = new async_hooks.AsyncResource('REQUEST_CONTEXT');
return asyncResource.runInAsyncScope(() => {
// 새로운 asyncId를 갖게 되었습니다
const asyncId = async_hooks.executionAsyncId();
// 빈 객체를 asyncId의 context 객체로 할당합니다
contexts[asyncId] = {}
return fn(contexts[asyncId]);
});
}
function getContext() {
const asyncId = async_hooks.executionAsyncId();
// 현재 asyncId에 연결된 context 객체를 가져옵니다
// 아무 것도 없다면 빈 객체를 줍니다
return contexts[asyncId] || {};
};
module.exports = {
initContext,
getContext,
};이제 잘 작동하나 확인해보는 간단한 코드를 짜봅시다.
const {initContext, getContext} = require('./context.js');
const logId = () => {
const context = getContext();
console.log(`My context id is: ${context.id}`);
}
initContext((context) => {
context.id = 1;
setTimeout(logId, 100);
setTimeout(logId, 300);
});
initContext((context) => {
context.id = 2;
setTimeout(logId, 200);
setTimeout(logId, 400);
});이 코드를 실행하면 다음과 같은 결과를 얻을 수 있습니다:
My context id is: 1
My context id is: 2
My context id is: 1
My context id is: 2다음은 뭘까요?
여기서 구현한 두 개의 함수는 매우 간단하지만, 데이터를 담아둘 context 객체를 만들고 이를 모든 함수에 넘길 필요가 없게끔 하는데 유용하게 사용할 수 있습니다.
실제 활용으로는 HTTP 요청마다 context를 만들고 요청 ID를 발급하고 로깅하는 함수에서 이 ID를 가져와야 하는 상황이 될 수 있습니다. 저는 또한 하나의 HTTP 요청에서모든 데이터베이스 요청을 모아서 동일 트랙잭션 내에서 실행하는 데에도 사용했습니다.
context를 만들어 데이터를 담을 때, 얼마나 많은 데이터를 담을지에 대해 조심할 필요가 있습니다. 이는 버그를 만들 수도 있는 엣지 케이스를 방지하기 위해 프로그램의 데이터 흐름에서 최대한 간단하게 유지되어야 합니다. 또한 TypeScript와 같은 도구를 사용할 때에 이런 context를 사용하면 현재 context가 무엇인지 확인할 수 없을 수도 있습니다.
async_hooks 은 아직 실험적인 기능이란 것을 알아두시기 바랍니다. 하지만 모험적인 것을 좋아한다면 한 번 사용해보세요!
