왜 요청 단위 추적 로그가 먼저 필요한가

Node.js API 서버에서 장애가 발생하면 가장 먼저 부딪히는 문제는 “어느 요청에서 시작된 오류인가”입니다. 로그가 많아도 요청 ID, 사용자 ID, 처리 구간, 외부 API 호출 시간이 서로 연결되어 있지 않으면 원인을 찾기 어렵습니다. 특히 Express, Fastify, NestJS처럼 비동기 처리가 많은 서버는 하나의 요청이 DB 조회, 캐시 조회, 외부 API 호출, 큐 발행으로 이어집니다. 이 흐름을 사람이 로그 시간순으로 맞추는 방식은 운영 장애 때 거의 실패합니다.

실무에서는 모든 로그에 공통 추적 필드를 붙이는 구조가 필요합니다. 대표 필드는 requestId, method, path, userId, tenantId, durationMs, statusCode입니다. 문제는 이 값을 매 함수 인자로 넘기기 시작하면 서비스 코드가 지저분해지고 누락도 잦아진다는 점입니다. Node.js의 AsyncLocalStorage는 요청이 시작될 때 컨텍스트를 만들고, 이후 이어지는 비동기 작업 안에서 같은 컨텍스트를 조회할 수 있게 해줍니다. 이를 이용하면 비즈니스 로직은 깔끔하게 유지하면서도 운영 로그는 요청 단위로 묶을 수 있습니다.

기본 설계 원칙

• 요청이 들어오는 가장 앞단 미들웨어에서 requestId를 만들거나 외부에서 받은 추적 헤더를 검증한 뒤 저장합니다.
• 로그 함수는 AsyncLocalStorage의 현재 컨텍스트를 자동으로 읽어 공통 필드를 붙입니다.
• 외부 API 호출, DB 쿼리, 큐 발행처럼 장애 원인이 되기 쉬운 경계 지점에는 반드시 시작과 종료 로그를 남깁니다.
• 비밀번호, 토큰, 주민번호, 결제 정보처럼 민감한 값은 로그에 쓰지 않고, 필요하면 마스킹된 식별자만 남깁니다.
• 로그 레벨은 info, warn, error를 분명히 나눕니다. 정상 요청 종료는 info, 재시도 가능한 지연은 warn, 사용자 요청 실패나 내부 예외는 error로 남기는 식입니다.

Express에서 적용하는 최소 예제

아래 예제는 외부 로깅 라이브러리 없이 구조를 보여주기 위한 코드입니다. 운영 환경에서는 pino, Winston, OpenTelemetry 연동을 붙여도 핵심은 같습니다. 요청 시작 시 AsyncLocalStorage에 requestId와 시작 시간을 넣고, 이후 logger 함수가 이 값을 자동으로 합쳐 JSON 로그를 출력합니다.

import express from "express";
import { AsyncLocalStorage } from "node:async_hooks";
import { randomUUID } from "node:crypto";

const app = express();
const requestStore = new AsyncLocalStorage();

function log(level, message, fields = {}) {
  const context = requestStore.getStore() || {};
  const payload = Object.assign({
    level,
    message,
    time: new Date().toISOString(),
    requestId: context.requestId,
    method: context.method,
    path: context.path,
    userId: context.userId
  }, fields);

  console.log(JSON.stringify(payload));
}

app.use((req, res, next) => {
  const requestId = req.get("x-request-id") || randomUUID();
  const startedAt = performance.now();

  requestStore.run({
    requestId,
    method: req.method,
    path: req.path,
    userId: req.get("x-user-id") || null
  }, () => {
    res.setHeader("x-request-id", requestId);

    res.on("finish", () => {
      log("info", "request_finished", {
        statusCode: res.statusCode,
        durationMs: Math.round(performance.now() - startedAt)
      });
    });

    next();
  });
});

app.get("/orders/:id", async (req, res, next) => {
  try {
    log("info", "order_lookup_started", { orderId: req.params.id });

    const order = await findOrder(req.params.id);

    if (!order) {
      log("warn", "order_not_found", { orderId: req.params.id });
      return res.status(404).json({ message: "not found" });
    }

    log("info", "order_lookup_finished", { orderId: req.params.id });
    res.json(order);
  } catch (error) {
    log("error", "order_lookup_failed", {
      errorName: error.name,
      errorMessage: error.message
    });
    next(error);
  }
});

app.listen(3000);

운영에서 자주 놓치는 지점

첫째, requestId를 응답 헤더로 돌려줘야 합니다. 고객센터, 프론트엔드, API 게이트웨이에서 같은 ID를 기준으로 문제 요청을 찾을 수 있기 때문입니다. 둘째, 에러 로그에 스택 전체를 무조건 남기기보다 errorName, errorMessage, code, cause 같은 검색 가능한 필드를 우선 분리해야 합니다. 스택은 필요하지만 검색 기준은 구조화된 필드가 더 강합니다.

셋째, 배치 작업과 큐 소비자에도 같은 방식을 적용해야 합니다. HTTP 요청만 추적하면 주문 생성 요청 이후 큐에서 실패한 메일 발송, 정산 처리, 재고 차감 로그가 분리됩니다. 큐 메시지를 발행할 때 requestId나 traceId를 메시지 메타데이터에 넣고, 소비자 시작 지점에서 AsyncLocalStorage 컨텍스트를 다시 열면 HTTP 이후의 비동기 처리까지 한 줄로 추적할 수 있습니다.

넷째, 로그 수집 시스템의 인덱스 비용을 생각해야 합니다. 모든 필드를 색인하면 비용이 커집니다. requestId, level, service, environment, statusCode, errorName, route 정도만 우선 검색 필드로 두고, 상세 payload는 필요할 때 원문 조회하는 방식이 안정적입니다. 운영 초기에 과한 로그를 남기는 것보다 장애 복구에 필요한 최소 필드를 꾸준히 남기는 편이 낫습니다.

점검 체크리스트

• 모든 요청 로그에 requestId, method, path, statusCode, durationMs가 포함되는지 확인합니다.
• 프론트엔드와 API 응답 헤더에서 같은 requestId를 확인할 수 있는지 테스트합니다.
• 외부 API, DB, 큐 같은 경계 지점마다 성공, 지연, 실패 로그가 구분되는지 확인합니다.
• 민감 정보가 로그에 찍히지 않도록 토큰, 쿠키, 비밀번호, 개인정보 필드를 차단합니다.
• 장애 상황에서 requestId 하나로 요청 시작, 내부 처리, 외부 호출, 최종 응답까지 이어서 조회할 수 있어야 합니다.