요청 하나를 로그로 꿰는 ID

배치 잡이 try/catch로 에러를 삼키고 조용히 끝나면 그 실패는 아무 데도 안 남는다. 로그아웃한 사용자의 /auth/refresh 401이 터미널을 도배해 진짜 에러를 묻어버리는 것도 결과가 같다. 둘 다 “에러 없음”처럼 보인다. 그런데 배치는 실패한 채 끝났고, 진짜 5xx는 401 더미에 묻혀 있다.

묻힌 에러가 나중에라도 보이게 만들기로 했다. 무엇이 언제 어디서 안 됐는지를 남기고, 남긴 걸 한 요청 단위로 정리할 수 있게 하는 작업이다.

그런데 로그를 아무리 남겨도 그중 어느 줄이 같은 요청에서 나온 것인지 모르면 읽을 수가 없다. 그래서 순서를 뒤집어, 남기는 것보다 알아볼 수 있게 만드는 쪽을 먼저 했다. 이 글은 거기까지고, 그 위에 얹은 분산추적과 에러 수집은 2편에 있다.

요청 흐름 어디서나 ID를 꺼내 쓰려면

“이 사용자가 결제하다 에러 났다는데 로그가 어디 있냐”를 찾으려면 요청 하나가 남긴 수십 줄이 같은 요청이라는 표시를 갖고 있어야 한다. 없으면 시간대로 grep해 눈으로 찾는 수밖에 없고, 요청이 계속 생기는 와중에는 그것도 너무 힘들다.

이렇게 요청 하나를 묶는 식별자를 correlation ID라 부른다. 만드는 것 자체는 쉬웠고, 요청 진입점에서 UUID 하나를 만들었다. 어려운 건 그 ID를 요청 흐름 어디서나 꺼내 쓰게 하는 것이다.

순진한 방법은 모든 서비스 메서드에 requestId 인자를 추가하는 것이다. 수백 개 시그니처를 오염시키니 비현실적이다. 로그 한 줄에 ID 붙이자고 중간에 있는 함수까지 전부 그 인자를 받아 넘기게 할 순 없다.

해법으로 쓴 건 AsyncLocalStorage다. Node가 비동기 호출 체인을 따라 유지해주는 요청 전용 보관함이다.

요청이 시작될 때 보관함을 한 번 열어두면, 그 요청에서 이어진 모든 await과 콜백이 별도 인자 없이 같은 보관함을 읽는다. Node 공식 문서는 이걸 다른 언어의 thread-local storage에 빗대 설명한다. 스레드 대신 비동기 컨텍스트에 묶인다는 차이만 있다.

같은 문서에 저수준 API를 직접 쓰는 것은 권장하지 않는다고 적혀 있다. 비동기 자원이 생기고 사라지는 것을 하나하나 훑는 createHook·executionAsyncResource 같은 것들이다.

헷갈리기 쉬운 게 하나 있다. 아래 코드도 node:async_hooks에서 AsyncLocalStorage를 가져온다. 권장하지 않는다는 건 그 모듈 전체가 아니라 그 안의 저수준 API 몇 개를 말한 것이고, AsyncLocalStorage는 거기 안 낀다. 컨텍스트 추적만 하겠다면 이쪽을 쓰라는 게 문서의 답이다.

import { AsyncLocalStorage } from "node:async_hooks"

const storage = new AsyncLocalStorage<{ requestId: string }>()

export const RequestContext = {
  run<T>(store: { requestId: string }, cb: () => T): T {
    return storage.run(store, cb)
  },
  getRequestId(): string | undefined {
    return storage.getStore()?.requestId
  },
}

컨텍스트를 여는 지점

요청 가장 바깥에서 requestId를 만들고 RequestContext.run으로 나머지 전부를 감싼다. 프론트나 게이트웨이가 X-Request-Id를 붙여 보냈으면 그 값을 그대로 쓰고, 없으면 새로 만든다. 앞에서 온 값을 이어 쓰면 프론트에서 시작한 요청 하나를 백엔드 로그까지 같은 ID로 따라갈 수 있다. 응답 헤더에도 같은 값을 실어 보내니 클라이언트도 자기 요청의 ID를 안다.

export function requestContextMiddleware(req, res, next): void {
  const incoming = req.headers["x-request-id"]
  const requestId =
    typeof incoming === "string" && incoming.trim()
      ? incoming.trim()
      : randomUUID()
  res.setHeader("X-Request-Id", requestId)
  RequestContext.run({ requestId }, () => next()) // 이후 모든 처리가 이 컨텍스트 안
}

처음엔 NestJS가 주는 미들웨어로 forRoutes('*')를 걸려고 했는데 안 됐다. NestJS 11이 Express 5를 쓰면서 라우트 패턴 문법이 바뀌었고, 모든 경로를 뜻하던 '*'가 그대로는 안 통한다.

그래서 라우트 매칭을 아예 거치지 않는 쪽으로 갔다. 평범한 Express 미들웨어를 app.use()로 제일 바깥에 걸면 모든 요청이 그걸 먼저 지난다. 그러면 가드부터 예외 필터까지 NestJS가 요청을 처리하는 모든 단계에서 requestId를 꺼낼 수 있다.

로거 한 곳에서 주입하기

requestId를 로그에 붙이겠다고 new Logger()를 부르는 64곳을 일일이 고칠 수는 없었다. 그렇게 하면 다음에 로거를 하나 더 만들 때 또 빠뜨린다. 대신 로거 한 곳에서 붙이기로 했다.

NestJS에서 new Logger()가 만드는 것은 껍데기다. 실제 출력은 NestFactory.create({ logger })로 등록해둔 앱 로거가 한다. 그러니 그 앱 로거만 갈아끼우면 된다. 메시지 앞에 현재 requestId를 붙이는 로거로 바꿔 등록하면, 이미 있는 64곳은 한 줄도 안 고치고 그 동작을 갖는다.

export class AppLogger extends ConsoleLogger {
  private withRequestId(message: unknown): unknown {
    const id = RequestContext.getRequestId()
    return id && typeof message === "string"
      ? `[req:${id}] ${message}`
      : message
  }
  log(message: unknown, ...rest: unknown[]): void {
    super.log(this.withRequestId(message), ...rest)
  }
  // error/warn/debug/verbose/fatal 동일 패턴
}

const app = await NestFactory.create(AppModule, { logger: new AppLogger() })

코드 64곳 중 0곳을 고치고도 모든 로그가 [req:abc-123] ... 형태가 됐다.

효과는 도입 시점보다 그 뒤에 드러났다. 이 글을 쓰는 시점에 new Logger() 호출처는 78곳이다. 도입 후 14곳이 늘어나는 동안 아무도 requestId를 신경 쓰지 않았고, 새로 생긴 로거들도 자동으로 묶였다.

호출처를 일일이 고치는 방식이었다면 규칙이 하나 남았을 것이다. “새 서비스를 만들면 로거에 requestId 붙이는 걸 잊지 마세요.” 그 규칙이 아예 필요 없어졌다.

의도적으로 남긴 v1 한계 두 가지는 받아들였다. 문자열이 아닌 메시지를 넘기면(logger.error(errObj)) 객체 앞에 글자를 붙일 수 없어 ID를 생략한다. 그리고 응답이 이미 끊긴 뒤에 던져진 예외는 그 요청의 보관함 밖에서 잡힐 수 있다. 둘 다 “대부분의 로그는 묶인다”를 해치지 않는 드문 경계라 v1으로 뒀다.

보관함을 여는 데 드는 시간

여기까지가 항상 도는 부분이다. 2편에 나오는 층들은 환경변수로 켜고 끄는데, 이 층에는 끄는 스위치를 안 뒀다. 끌 이유가 없다고 판단한 근거가 “보관함 하나 여는 게 얼마나 들겠나”라는 짐작이었고, 짐작으로 두기 싫어 재봤다.

요청 하나가 await을 여섯 번 거치고 로그를 열 줄 남기는 것을 흉내낸 함수를 두 벌 만들었다. 한쪽은 그냥 돌리고, 다른 쪽은 storage.run()으로 감싼 뒤 로그 한 줄마다 getStore()를 부른다. 워밍업 3만 회를 버리고 30만 회를 돌려 나눈 값이다(Node v25.2.1, 로컬 맥).

감싸는 데 201ns가 들고, 그 안에서 값을 꺼내는 건 한 번에 11.6ns다. 로그를 열 줄 남기는 요청이면 다 합쳐 352ns이고, 밀리초로 옮기면 0.0004ms다. DB를 한 번만 다녀와도 몇 밀리초가 드는 요청에서 이 값은 소수점 아래로 사라진다. 요청 진입점에서 부르는 randomUUID()도 83ns라, ID를 만들고 보관함을 여는 것을 전부 합쳐 마이크로초를 안 넘는다.

이건 HTTP도 DB도 없는 마이크로벤치마크다. 실제 요청은 훨씬 무겁고, 비동기 컨텍스트가 깊게 중첩되면 감싸는 비용도 이보다 오를 수 있다. 그래도 어느 자릿수인지는 확인했으니, “끌 이유가 없다”는 판단을 짐작이 아니라 나노초 단위 값으로 바꿔 적을 수 있게 됐다.

401 로그부터 줄이기

ID로 로그를 묶고 나서 한 첫 작업은 늘리는 게 아니라 줄이는 거였다. 모든 HTTP 요청을 한 줄씩 찍으면 성공 요청까지 전부 흘러가고, 그중 최악은 401이었다.

401은 인증이 안 됐다는 뜻의 응답 코드다. 토큰이 만료된 클라이언트는 /auth/refresh를 계속 때린다. 그 401이 무한히 쌓이면 정작 봐야 할 5xx가 그 안에 묻힌다. 5xx는 서버가 잘못됐다는 뜻의 응답 코드다.

LOG_HTTP 환경변수로 상세도를 세 단계로 나눴다. all(전부)·summary(기본)·off(5xx만).

// summary : 느린(>1s) 요청과 5xx·주요 4xx만. 401(미인증)은 루틴 노이즈라 침묵
export type HttpLogMode = "all" | "summary" | "off"

기본값 summary는 느린 요청(>1s)과 에러만 남긴다. 성공 요청을 한 줄씩 찍던 걸 끄고, 401은 침묵시킨다. 대신 응답 시간을 항상 같이 찍는다. 그 한 줄만 있어도 N+1이나 느린 쿼리가 따로 프로파일링을 안 해도 눈에 띈다.

GET /companies/:id/documents 200 1340ms   ← summary에서도 남는다(느림)
POST /auth/refresh 401 3ms                 ← summary에서 침묵(노이즈)

한 가지 함정은 이중 로그였다. 요청 앞뒤를 감싸는 인터셉터가 에러를 찍고, 예외를 응답으로 바꾸는 예외 필터도 또 찍으면 같은 에러가 두 번 뜬다. 그래서 summary에선 인터셉터가 에러 로깅을 예외 필터에 위임하고 자기는 성공·느린 요청만 본다.

붙이고 나서 로그가 줄었다

관측을 붙였는데 로그 양은 늘어난 게 아니라 줄었다. 성공 요청을 한 줄씩 찍던 걸 끄고, 401을 침묵시키고, 인터셉터와 예외 필터가 같은 에러를 두 번 찍던 걸 한 번으로 합쳤기 때문이다. 남은 줄은 전부 requestId로 묶여 있으니 하나를 잡으면 그 요청이 지나간 나머지가 따라 나온다.

실제로 도는지는 나중에 로그를 세면서 확인했다. 운영 백엔드와 배치의 5개월치 로그에서 [req: 접두사가 붙은 줄이 8,813건이다.

여기까지는 로그를 읽을 수 있게 만든 것뿐이고, 아직 안 남는 실패가 남아 있다. 배치가 catch로 삼킨 에러는 로그에도 안 찍히니 묶을 것 자체가 없다. 그걸 잡으려고 얹은 층들은 2편에 있다.