NestJS에서 AsyncLocalStorage로 traceId 추적하기

JavaScript

NestJS에서 AsyncLocalStorage로 traceId 추적하기

MIRACLE LIFE 2026. 5. 23. 14:54

한 요청에서 발생하는 모든 로그에 같은 식별자(traceId)를 주입하여 추적하고 싶다.
처음엔 NestJS의 Request Scope로 풀었지만, 왜 결국 AsyncLocalStorage로 바꿨는지에 대해 기록한다.

배경: 왜 traceId가 필요한가

서버에서 한 번의 HTTP 요청이 처리되는 동안 여러 곳에서 로그가 찍힌다.

미들웨어: "요청이 들어왔다"
컨트롤러/서비스: "유저를 조회한다"
레포지토리: "DB 쿼리를 날렸다"
인터셉터: "응답을 보낸다 (XXms 걸림)"

운영 중 장애가 났을 때, 우리가 보고 싶은 건 "이 요청 하나가 만들어낸 로그들" 이다. 다른 요청들의 로그와 뒤섞이면 디버깅이 불가능하다.

그래서 요청이 들어오는 순간 식별자를 하나 발급하고, 그 요청 안에서 찍히는 모든 로그에 그 식별자를 박는다. 이걸 보통 traceId(혹은 correlationId, requestId)라고 부른다.

{ "level": "info", "traceId": "abc-123", "msg": "user fetched" }
{ "level": "info", "traceId": "abc-123", "msg": "post fetched" }
{ "level": "info", "traceId": "def-456", "msg": "user fetched" }   // 다른 요청

이렇게 되면 로그 시스템(Datadog, ELK, NewRelic 등)에서 traceId="abc-123"로 필터만 걸면 그 요청의 전체 흐름을 한 화면에 볼 수 있다.

NestJS Request Scope

NestJS는 모든 provider를 기본적으로 싱글톤으로 만든다. 앱이 뜰 때 한 번 인스턴스화되고, 죽을 때까지 그 인스턴스를 재사용한다.

그런데 NestJS는 두 가지 다른 스코프를 더 제공한다.

Scope	설명
DEFAULT	싱글톤. 앱당 1개 인스턴스.
REQUEST	요청당 1개 인스턴스. 매 HTTP 요청마다 새로 만들고, 응답이 끝나면 GC.
TRANSIENT	주입할 때마다 1개. 거의 안 씀.

Scope.REQUEST는 요청 단위 컨텍스트를 다룰 때 매력적이다. 매 요청마다 새 인스턴스가 만들어지므로 "이 요청의 traceId는 이 인스턴스의 필드다" 라고 단순하게 둘 수 있다.

그래서 처음엔 이렇게 짰다.

@Injectable({ scope: Scope.REQUEST })
export class AppLogger implements LoggerService {
  constructor(
    @Inject(REQUEST)
    private readonly request: (Request & { traceId?: string }) | undefined,
  ) { /* winston 인스턴스 생성 */ }

  log(message: unknown, context?: string) {
    this.logger.info(message, {
      traceId: this.request?.traceId ?? 'unknown',
      context,
    });
  }
}

미들웨어에서 traceId를 발급해 req.traceId에 넣어두면, 로거 인스턴스가 그 요청의 req를 들고 있으므로 자동으로 traceId가 메타데이터에 들어간다. 깔끔해 보였다.

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction) {
    const traceId = req.header('x-correlation-id') ?? randomUUID();
    req.traceId = traceId;
    res.setHeader('x-correlation-id', traceId);
    next();
  }
}

기대한 대로 작동은 한다. 그런데 이 방식에는 약간의 문제가 존재한다.

Request Scope의 문제

1. 미들웨어와 인터셉터에서 logger를 쓰지 못해 console.log로 우회

NestJS에서 클래스 미들웨어와 인터셉터는 기본적으로 앱이 뜰 때 한 번 인스턴스화되는 싱글톤으로 동작한다. 부트스트랩 시점엔 아직 어떤 요청도 들어오지 않았다.

여기에 Scope.REQUEST인 AppLogger를 주입할 수 없다.

부트스트랩 시점에는 request 컨텍스트가 없어 request-scoped 의존성을 정상적으로 해소할 수 없다.

따라서 미들웨어와 인터셉터 안에서는 그냥 console.log를 사용하여 로그를 남겼다.

// LoggerMiddleware
console.log(JSON.stringify({ traceId, type: '[REQUEST]', method, path }));

// LoggingInterceptor
console.log(JSON.stringify({ traceId, type: '[RESPONSE]', statusCode, latencyMs }));

결과적으로 같은 로깅이라는 관심사를 두고 winston 기반 logger와 console.log가 섞여 있는 일관성 없는 코드가 됐다.

포맷도 다르고, transport도 다르고, 코드 베이스에서 로그를 찾을 때 두 군데를 봐야 한다.

2. 성능 비용 발생

미들웨어/인터셉터에서 console.log를 사용한다고 해결된 게 아니었다. logger를 주입받던 모든 일반 서비스 가 request scope의 영향권 안에 있었다.

NestJS 공식 문서의 Scope hierarchy 섹션은 이렇게 동작을 명시한다.

"The REQUEST scope bubbles up the injection chain. A controller that depends on a request-scoped provider will, itself, be request-scoped."

이 동작은 한 번 request scope에 발을 들이면, 그 의존성을 쓰는 모든 클래스가 request scope로 끌려간다는 뜻이다.

이 케이스에 그대로 대입해보면

SampleController <- SampleService <- AppLogger(REQUEST)

AppLogger가 request-scoped이므로 SampleService는 자동으로 request-scoped가 되고, 그걸 주입한 SampleController도 request-scoped가 된다. 의존성 사슬을 따라 줄줄이 끌려간다.

NestJS 공식 문서의 Durable providers 섹션은 이 케이스를 거의 정확히 짚는다.

"Having a common provider that most providers depend on (think of a database connection, or a logger service), automatically converts all those providers to request-scoped providers as well."

매 요청마다 컨트롤러, 서비스, 그리고 그것들의 의존성 전부가 새로 인스턴스화되고 GC된다. 트래픽이 적을 땐 체감이 거의 없지만, 동시 요청이 많아질수록 비용이 누적된다.

정리하면

console.log 우회는 미들웨어/인터셉터를 건드리지 않으려고 한 회피책
진짜 성능 비용은 logger를 정상적으로 주입하던 일반 서비스 쪽에서 이미 발생하고 있었다

3. 매 요청마다 winston 인스턴스가 새로 만들어진다

AppLogger의 생성자는 winston.createLogger({...})를 호출한다. request scope이기 때문에 이게 요청마다 한 번씩 실행 된다.

transport 설정, 포맷터 조립, 메타데이터 초기화 등은 한 번만 하면 충분한 일이다. 굳이 매 요청 비용을 지불할 필요가 없다.

해결책: AsyncLocalStorage

AsyncLocalStorage(이하 ALS)는 Node.js 12.17부터 표준 모듈(node:async_hooks)에 포함된 기능이다. 한 줄로 표현하면 다음과 같다.

비동기 호출 체인 전체에 걸쳐 살아남는 컨텍스트 저장소

1. 다른 언어와 비교

다른 언어를 써본 사람이라면 Thread-Local Storage(TLS) 를 떠올리면 가장 빠르다. "이 스레드만의 변수"를 두는 그 기능.

단, Node.js는 싱글스레드 이벤트 루프이기 때문에 "스레드별"이 아니라 "async chain별" 이다.

2. 어떻게 동작하는지 코드로 보기

import { AsyncLocalStorage } from 'node:async_hooks';

const als = new AsyncLocalStorage<{ traceId: string }>();

als.run({ traceId: 'abc-123' }, () => {
  setTimeout(() => {
    console.log(als.getStore()); // { traceId: 'abc-123' }
  }, 100);

  Promise.resolve().then(() => {
    console.log(als.getStore()); // { traceId: 'abc-123' }
  });
});

console.log(als.getStore()); // undefined (run 콜백 밖)

run(store, callback)으로 컨텍스트를 시작하면, 그 콜백 안에서 시작된 모든 비동기 작업(Promise 체인, await, setTimeout, 이벤트 핸들러 등)에서 getStore()로 같은 store를 꺼낼 수 있다.

3. 해결

미들웨어에서 als.run({ traceId }, () => next())로 컨텍스트를 연다.
그 안에서 next()가 실행되면, 이후 모든 인터셉터/컨트롤러/서비스/레포지토리가 같은 컨텍스트에서 동작한다.
로거는 그냥 ALS에서 traceId를 꺼내쓰면 된다.
로거가 더 이상 request scope일 필요가 없다 = 싱글톤으로 회귀할 수 있다.

스코프 전염 문제도, winston을 매번 생성하는 문제도 한 번에 해결된다.

실제 리팩토링

Step 1. ALS 래퍼 만들기

ALS(AsyncLocalStorage)자체는 NestJS와 무관한 순수 Node API지만, NestJS DI에 태우면 테스트가 깔끔해진다.

// src/logger/request-context.service.ts
import { Injectable } from '@nestjs/common';
import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContextStore = {
  traceId: string;
};

@Injectable()
export class RequestContextService {
  private readonly storage = new AsyncLocalStorage<RequestContextStore>();

  run<T>(store: RequestContextStore, callback: () => T): T {
    return this.storage.run(store, callback);
  }

  getTraceId(): string | undefined {
    return this.storage.getStore()?.traceId;
  }
}

Step 2. AppLogger를 싱글톤으로 되돌리기

// Before
@Injectable({ scope: Scope.REQUEST })
export class AppLogger {
  constructor(@Inject(REQUEST) private readonly request: ...) {}

  private getRequestMeta() {
    return { traceId: this.request?.traceId ?? 'unknown' };
  }
}

// After
@Injectable() // = Scope.DEFAULT (싱글톤)
export class AppLogger {
  constructor(private readonly requestContext: RequestContextService) {}

  private getRequestMeta() {
    return { traceId: this.requestContext.getTraceId() ?? 'unknown' };
  }
}

@Inject(REQUEST)도, Scope.REQUEST도 사라졌다. 인스턴스는 앱당 1개. winston도 앱당 1개.

Step 3. 미들웨어에서 ALS 컨텍스트 시작

여기가 이번 리팩토링의 핵심이다.

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  constructor(
    private readonly logger: AppLogger,
    private readonly requestContext: RequestContextService,
  ) {}

  use(req: Request, res: Response, next: NextFunction) {
    const traceId = req.header('x-correlation-id') ?? randomUUID();
    res.setHeader('x-correlation-id', traceId);

    this.requestContext.run({ traceId }, () => {
      this.logger.log(`${req.method} ${req.url}`, '[REQUEST]', {
        method: req.method,
        path: req.url,
      });
      next(); // ← 이 안에서 시작된 모든 비동기 체인은 같은 traceId 컨텍스트
    });
  }
}

중요한 포인트는 next()가 반드시 run() 콜백 안에서 호출되어야 한다는 것이다. 그래야 라우트 핸들링 전체가 ALS 컨텍스트 안에 들어간다.

// ❌ BAD - 컨텍스트 밖에서 next 호출
this.requestContext.run({ traceId }, () => {});
next(); // 여기는 ALS 밖

// ✅ GOOD
this.requestContext.run({ traceId }, () => {
  next();
});

Step 4. 인터셉터는 그냥 logger를 받아쓰면 끝

@Injectable()
export class LoggingInterceptor implements NestInterceptor {
  constructor(private readonly logger: AppLogger) {} // 싱글톤이라 자유롭게 주입 OK

  intercept(context: ExecutionContext, next: CallHandler) {
    const httpContext = context.switchToHttp();
    const request = httpContext.getRequest<Request>();
    const response = httpContext.getResponse<Response>();
    const startedAt = Date.now();

    return next.handle().pipe(
      tap(() => {
        this.logger.log(
          `${request.method} ${request.url} ${response.statusCode}`,
          '[RESPONSE]',
          { latencyMs: Date.now() - startedAt },
        );
        // traceId는 ALS에서 자동으로 채워짐
      }),
    );
  }
}

console.log 우회가 사라지고, 모든 곳에서 같은 logger를 쓴다.

Step 5. LoggerModule로 묶고 글로벌로 노출

NestJS DI는 모듈 단위로 인스턴스를 만든다. 한 클래스를 두 모듈에서 각각 providers에 넣으면, 싱글톤이라도 인스턴스가 두 개 만들어진다.

이걸 막기 위해 LoggerModule로 묶고 @Global()을 붙였다.

@Global()
@Module({
  providers: [AppLogger, RequestContextService],
  exports: [AppLogger, RequestContextService],
})
export class LoggerModule {}

AppModule에서 한 번만 import: [LoggerModule]해두면 어디서든 같은 인스턴스를 주입받을 수 있다.

조심해야 할 ALS의 특징

1. 일부 비동기 패턴은 컨텍스트가 끊긴다

async/await, Promise 체인, setTimeout, setImmediate 같은 일반적인 비동기는 ALS를 잘 통과한다. 하지만 다음과 같은 상황에서는 끊길 수 있다.

EventEmitter 패턴: emit 시점이 아니라 listener가 등록된 시점의 컨텍스트가 유지된다. 부트스트랩 시점에 등록된 리스너 안에서는 traceId가 없다.
커넥션 풀 / Worker thread 경계: native binding을 거치는 일부 라이브러리는 컨텍스트를 잃을 수 있다.

이런 경우엔 ALS에서 traceId를 꺼내 명시적으로 같이 넘기는 식으로 우회한다.

2. 미들웨어 바깥의 로그는 traceId가 없다

부트스트랩 로그, cron 작업, 백그라운드 태스크 등 HTTP 요청 컨텍스트 밖에서 찍히는 로그는 getStore()가 undefined라 traceId: 'unknown'으로 찍힌다. 정상 동작이다.

cron이라면 cron의 진입점에서 별도로 컨텍스트를 만들어주면 된다.

@Cron('0 * * * *')
handleHourly() {
  this.requestContext.run({ traceId: `cron-${randomUUID()}` }, () => {
    this.doWork();
  });
}

3. ALS의 오버헤드

async_hooks를 활성화하면 비동기 작업마다 약간의 오버헤드가 생긴다. Node.js 16 이후로는 V8 자체에 ALS 전용 최적화 경로가 있어서 영향이 매우 작다. 일반적인 웹 서버 워크로드에서는 측정 가능한 영향이 거의 없다.

정리

	Before	After
Logger scope	REQUEST	DEFAULT (싱글톤)
traceId 전달 방법	req.traceId 직접 mutate	ALS로 자동 전파
미들웨어/인터셉터 로그	console.log 우회	일관된 logger 사용
winston 인스턴스	요청마다 새로 생성	앱당 1번 생성
Scope bubbling	발생	없음

Request Scope는 강력한 도구지만, 로거처럼 모든 곳에서 쓰이는 의존성에는 어울리지 않는다. 한 곳에서 request scope를 쓰면 거기에 닿는 모든 코드가 끌려간다.

AsyncLocalStorage에 한 번 익숙해지면 traceId 외에도 같은 "요청 단위로 따라다녀야 하는 것들"을 깔끔하게 다룰 수 있다.

참고

'JavaScript' 카테고리의 다른 글

NestJS Custom Decorator로 유저 인증 처리하기 (0)	2025.02.19
TypeORM의 save() 사용 시 데이터 변경 감지 원리 이해하기 (0)	2024.12.15
프로토타입 (0)	2024.05.22
this / 콜백 함수 / 클로저 (0)	2024.05.20
자바스크립트의 실행 컨텍스트 (0)	2024.05.19

현재글NestJS에서 AsyncLocalStorage로 traceId 추적하기

개발블로그

GitHub Actions, javascript, mysql 서버 설정, nestjs, GitHub, cicd, RDBMS, db, 운영체제, authentication, SQL, NoSQL, codedeploy, Git, database, 동시성문제, 클린 셧다운, Nest.js, MySQL, mongoDB,

Today :
Yesterday :

개발블로그