Node.js async_hooks 컨텍스트 추적 심화

Introduction

Node.js의 비동기 특성으로 인해 요청 간의 컨텍스트를 추적하는 것은 어려운 문제입니다. async_hooks 모듈은 비동기 작업의 생명 주기를 추적하여 컨텍스트를 관리하는 강력한 도구입니다. 이번 포스트에서는 asyncLocalStorage를 활용한 컨텍스트 추적 기법을 살펴보겠습니다.

Environment

node --version
# v20.11.0

# async_hooks는 Node.js 기본 내장 모듈
node -e "console.log(typeof require('async_hooks'))"
# object

Problem

여러 비동기 요청이 동시에 처리될 때 로그에 request ID가 올바르게 연결되지 않는 문제가 있었습니다:

const express = require('express');
const app = express();

app.get('/api/user', async (req, res) => {
    const requestId = generateRequestId();
    console.log(`[${requestId}] Starting user fetch`);

    // 비동기 작업 중 컨텍스트 상실
    await someAsyncOperation();

    console.log(`[${requestId}] Completed`); // requestId가 다를 수 있음
    res.json({ requestId });
});

// 로그 출력
// [req-abc123] Starting user fetch
// [req-def456] Completed  // 잘못된 ID!

Analysis

Node.js 비동기 컨텍스트 문제

Request A → middleware → handler → async DB call → response
Request B → middleware → handler → async API call → response
         ↘            ↘            ↘
          컨텍스트 A     컨텍스트 B     컨텍스트 섞임!

async_hooks 이벤트 타입

이벤트	설명	사용 용도
init	비동기 작업 생성	리소스 추적
before	비동기 작업 시작 전	컨텍스트 저장
after	비동기 작업 완료 후	컨텍스트 복원
destroy	비동기 작업 파괴	리소스 정리

Solution

1. AsyncLocalStorage 기본 사용법

const { AsyncLocalStorage } = require('async_hooks');

// 컨텍스트 스토리지 생성
const asyncLocalStorage = new AsyncLocalStorage();

// 요청 ID 생성 함수
function generateRequestId() {
    return `req-${Date.now()}-${Math.random().toString(36).substr(2, 9)}`;
}

// Express 미들웨어
function requestIdMiddleware(req, res, next) {
    const requestId = req.headers['x-request-id'] || generateRequestId();

    asyncLocalStorage.run({ requestId, startTime: Date.now() }, () => {
        req.requestId = requestId;
        res.setHeader('X-Request-Id', requestId);

        // 요청 완료 시 로그
        res.on('finish', () => {
            const store = asyncLocalStorage.getStore();
            if (store) {
                const duration = Date.now() - store.startTime;
                console.log({
                    requestId: store.requestId,
                    method: req.method,
                    path: req.path,
                    statusCode: res.statusCode,
                    duration: `${duration}ms`,
                });
            }
        });

        next();
    });
}

// 현재 컨텍스트에서 요청 ID 가져오기
function getRequestId() {
    const store = asyncLocalStorage.getStore();
    return store?.requestId || 'unknown';
}

// 앱에 미들웨어 적용
app.use(requestIdMiddleware);

// 로그 유틸리티
const logger = {
    info: (message, data = {}) => {
        const requestId = getRequestId();
        console.log(JSON.stringify({
            level: 'info',
            requestId,
            message,
            ...data,
            timestamp: new Date().toISOString(),
        }));
    },
    error: (message, error) => {
        const requestId = getRequestId();
        console.error(JSON.stringify({
            level: 'error',
            requestId,
            message,
            error: error?.message,
            stack: error?.stack,
            timestamp: new Date().toISOString(),
        }));
    },
};

2. 데이터베이스 쿼리 추적

const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();

// 쿼리 추적 스토리지
const queryStore = new AsyncLocalStorage();

class QueryTracker {
    constructor() {
        this.queries = [];
    }

    track(query, params) {
        const context = queryStore.getStore();
        if (context) {
            context.queries.push({
                query,
                params,
                timestamp: Date.now(),
            });
        }
    }

    getQueries() {
        const context = queryStore.getStore();
        return context?.queries || [];
    }
}

const queryTracker = new QueryTracker();

// MongoDB 쿼리 미들웨어
function trackingMiddleware(req, res, next) {
    queryStore.run({ queries: [] }, () => {
        // 쿼리 시작
        const originalExec = mongoose.Query.prototype.exec;
        mongoose.Query.prototype.exec = function() {
            const queryStr = this.getQuery();
            const modelName = this.model.modelName;

            queryTracker.track(`${modelName}: ${JSON.stringify(queryStr)}`);
            return originalExec.apply(this, arguments);
        };

        // 응답 전 쿼리 정보 추가
        res.on('finish', () => {
            const queries = queryTracker.getQueries();
            res.setHeader('X-DB-Queries', queries.length);
        });

        next();
    });
}

3. 비동기 스택 추적

const { AsyncLocalStorage } = require('async_hooks');
const { executionAsyncId } = require('async_hooks');

const asyncLocalStorage = new AsyncLocalStorage();

// 스택 트레이스 생성 함수
function getAsyncStack() {
    const store = asyncLocalStorage.getStore();
    if (!store) return [];

    const stack = [];
    let currentId = executionAsyncId();

    while (currentId && store.asyncIds.has(currentId)) {
        stack.push(store.asyncIds.get(currentId));
        currentId = store.parentIds.get(currentId) || 0;
    }

    return stack.reverse();
}

// 비동기 작업 추적 미들웨어
function asyncTracingMiddleware(req, res, next) {
    const asyncIds = new Map();
    const parentIds = new Map();

    asyncLocalStorage.run({
        asyncIds,
        parentIds,
        requestId: generateRequestId(),
    }, () => {
        // async_hooks 생성
        const { createHook } = require('async_hooks');

        const hook = createHook({
            init(asyncId, type, triggerAsyncId) {
                const store = asyncLocalStorage.getStore();
                if (store) {
                    store.asyncIds.set(asyncId, type);
                    store.parentIds.set(asyncId, triggerAsyncId);
                }
            },
        });

        hook.enable();

        // 요청 완료 시 해제
        res.on('finish', () => {
            hook.disable();
        });

        next();
    });
}

4. 성능 메트릭 추적

const { AsyncLocalStorage } = require('async_hooks');

const asyncLocalStorage = new AsyncLocalStorage();

class PerformanceMetrics {
    constructor() {
        this.metrics = new Map();
    }

    start(label) {
        const store = asyncLocalStorage.getStore();
        if (store) {
            store.metrics.set(label, {
                start: process.hrtime.bigint(),
                type: 'start',
            });
        }
    }

    end(label) {
        const store = asyncLocalStorage.getStore();
        if (store) {
            const metric = store.metrics.get(label);
            if (metric) {
                const duration = process.hrtime.bigint() - metric.start;
                metric.duration = Number(duration) / 1000000; // ms
                metric.type = 'complete';
            }
        }
    }

    getMetrics() {
        const store = asyncLocalStorage.getStore();
        return store?.metrics || new Map();
    }
}

const perfMetrics = new PerformanceMetrics();

// 사용 예시
app.get('/api/data', async (req, res) => {
    perfMetrics.start('database');
    const data = await db.query('SELECT * FROM users');
    perfMetrics.end('database');

    perfMetrics.start('processing');
    const processed = processData(data);
    perfMetrics.end('processing');

    const metrics = Object.fromEntries(perfMetrics.getMetrics());
    res.json({ data: processed, metrics });
});

Lessons Learned

AsyncLocalStorage 활용: 요청 컨텍스트를 추적하기 위해 AsyncLocalStorage를 사용하세요
Request ID 전파: 모든 비동기 작업에 request ID를 전파하여 로그 추적성을 높이세요
히스토리 관리: async_hooks 히스토리는 적절히 해제하여 메모리 누수를 방지하세요
성능 영향: async_hooks는 성능 오버헤드가 있으므로 필요에 따라 활성화하세요
에러 핸들링: 비동기 컨텍스트에서 에러가 발생할 때 올바르게 처리되도록 하세요

This blog does not accept any external sponsorships, affiliate marketing, or ad revenue.