[업무일지] 서비스마다 따로 놀던 요청 ID를 trace_id로 통일

게시 2026/01/15

By 영킴 12 분 읽는 시간

서비스마다 요청에 UUID를 하나 찍어 로그를 묶고 있었습니다. 한 서비스 안에서만 통하는 ID였죠. OpenTelemetry를 넣으면서 그 UUID를 trace_id로 바꿔, 요청 하나를 서비스들을 건너 따라갈 수 있게 했습니다. 대신 로그는 OTel로 보내지 않았습니다. 기존 로그 파이프라인을 그대로 두고, 공유되는 traceId로만 트레이스와 이었습니다.

한 요청을 여러 서비스가 나눠 처리하는 구조입니다. 셀러용 API가 요청을 받으면 회원·정산 쪽으로 내부 호출이 이어집니다. 문제 하나를 쫓을 때 이 서비스 저 서비스 로그를 오가야 하는데, 그걸 하나로 묶어줄 공통 ID가 없었습니다. 정보보호 관리체계 인증(ISMS) 심사를 준비하며 로그와 접속 기록을 함께 정리하던 시기입니다. Java 21, Spring Boot 3.3.x, OpenTelemetry Java 2.x(Spring Boot starter)를 쓰는 환경이고, 이 글에서 손댄 건 그중 분산 추적입니다.

서비스마다 자기 UUID를 찍고 있었다

원래는 요청이 들어오면 필터에서 UUID를 하나 만들어 MDC에 넣고, 로그 패턴에 그걸 찍었습니다.

  
// Java 21, Spring Boot 3.3.x
// 요청 필터: 요청마다 UUID 를 만들어 로그를 묶는다
MDC.put(MdcKey.CONTEXT_ID.name(), UUID.randomUUID().toString());

[%d{...}] [%5p] [%15.15thread] [%logger{39}] [%X{CONTEXT_ID:-NO CONTEXT ID}] - %m%n

한 서비스 안에서는 이걸로 충분합니다. 같은 CONTEXT_ID가 찍힌 로그를 모으면 그 요청이 그 서비스에서 뭘 했는지 보이니까요. 문제는 그 ID가 서비스 경계를 못 넘는다는 점입니다. 셀러용 API가 만든 UUID는 거기서 끝이고, 내부 호출을 받은 회원 서비스는 자기 UUID를 새로 찍습니다. 그래서 한 요청이 서비스 셋을 거치면 로그에는 서로 아무 상관없어 보이는 UUID가 셋 남습니다. 정작 그 셋이 같은 요청의 앞부분과 중간과 끝이라는 사실은 로그 어디에도 안 적혀 있어서, 장애를 쫓다 서비스 경계를 넘을 때마다 시간과 요청 내용으로 ‘아마 이게 그다음일 것’이라고 사람이 짐작해서 이어 붙여야 했죠.

trace_id로 바꾸니 요청이 서비스를 건너 이어졌다

OpenTelemetry를 넣으면서 이 UUID를 OTel의 trace_id로 갈아끼웠습니다. OTel은 tracecontext 전파 규격으로 trace_id를 HTTP 헤더에 실어 다음 서비스로 넘깁니다. 그러니 내부 호출을 받은 서비스는 새 ID를 만드는 게 아니라 같은 trace_id를 이어받습니다. 요청 하나에 id 하나가 서비스 끝까지 따라가는 겁니다.

필터에서 UUID를 만들던 자리를 현재 span에서 trace_id를 꺼내는 걸로 바꿨습니다.

  
// OpenTelemetry 의 현재 span 에서 trace_id 를 꺼내 MDC 에 넣는다
Span currentSpan = Span.current();
SpanContext spanContext = currentSpan.getSpanContext();
if (spanContext.isValid()) {
    MDC.put("trace_id", spanContext.getTraceId());
    MDC.put("span_id", spanContext.getSpanId());
}

[%d{...}] [%5p] [%15.15thread] [%logger{39}] [traceId=%X{trace_id:-}] - %m%n

CONTEXT_ID enum은 지웠습니다. 이제 로그에 찍히는 상관관계 ID는 트레이싱 백엔드에서 보는 trace_id와 같은 값입니다. 로그에서 trace_id를 복사해 트레이싱 화면에 넣으면 그 요청의 전체 경로가 뜨고요.

span_id는 MDC에 넣어는 뒀지만 로그 패턴에는 안 찍었습니다. 로그를 트레이스에 잇는 데는 trace_id 하나면 되고, span_id까지 매 줄에 붙이면 눈으로 읽을 때 자리만 차지하거든요. 필요하면 나중에 패턴에 더하면 되니까 MDC에는 남겨뒀습니다.

로그는 OTel로 보내지 않았다

여기서 결정을 하나 했습니다. OTel은 트레이스만이 아니라 로그도 내보낼 수 있습니다. Logback appender를 붙이면 로그가 OTLP로 콜렉터에 실려 갑니다. 처음엔 이것도 켰습니다.

  
otel:
  propagators: tracecontext
  exporter:
    otlp:
      endpoint: "http://otel-collector:4318"
      protocol: http/protobuf
  traces:
    exporter: otlp
  metrics:
    exporter: otlp
  instrumentation:
    micrometer:
      enabled: true
    logback-appender:
      enabled: false   # 로그는 OTel 로 보내지 않는다
    spring-webmvc:
      enabled: true

그런데 켜 놓고 보니 이게 필요가 없었습니다. 로그는 이미 표준출력으로 나가 인프라가 수집하는 경로가 멀쩡히 있었는데, 여기에 OTel appender까지 붙이면 같은 로그가 기존 경로와 OTLP 두 갈래로 나가면서 수집하고 저장하는 비용만 두 배로 들고 정작 새로 얻는 건 없는 상태가 됩니다. 로그와 트레이스를 잇는 건 로그 줄에 찍힌 trace_id 하나면 되지, 로그 본문 자체를 트레이스와 같은 파이프로 실어 보낼 이유가 없었거든요. 그래서 appender를 도로 껐고, 쓰지도 않는 로그 익스포터 설정도 지웠습니다. OTel로는 트레이스와 메트릭만 내보냅니다.

이 판단의 대가는 로그와 트레이스가 다른 시스템에 나뉘어 산다는 겁니다. 둘을 잇는 건 trace_id라는 공통 값 하나뿐이고요. 한 화면에서 로그와 트레이스를 같이 검색하고 싶어지면 그때 다시 봐야 합니다. 지금은 그럴 필요가 크지 않다고 봤습니다.

비동기로 넘어가면 트레이스가 끊겼다

한 가지 걸린 게 있었습니다. MDC도 OTel 컨텍스트도 스레드에 매여 있습니다. 요청 스레드에서 @Async로 일을 넘기면 새 스레드에는 그 컨텍스트가 없어서, 거기서 남긴 로그에는 trace_id가 안 찍히고 거기서 만든 span은 원래 트레이스에서 떨어져 나갑니다.

MDC를 async 스레드로 복사하는 TaskDecorator는 원래 있었습니다. CONTEXT_ID를 넘기려고요. 여기에 OTel 컨텍스트도 같이 잡아 넘기게 고쳤습니다.

  
public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> mdc = MDC.getCopyOfContextMap();
        Context otel = Context.current(); // OTel 컨텍스트도 같이 잡는다
        return () -> {
            if (mdc != null) MDC.setContextMap(mdc);
            try (var ignored = otel.makeCurrent()) { // 없으면 async span 이 트레이스에서 떨어진다
                runnable.run();
            }
        };
    }
}

트레이싱을 나중에 얹을 때 이런 자리가 조용합니다. 동기 경로는 자동 계측이 알아서 이어주는데, 우리가 손으로 스레드를 넘기는 자리는 우리가 컨텍스트를 넘겨줘야 하거든요. 안 넘기면 에러가 나거나 테스트가 빨개지는 게 아니라, 그 async 안에서 벌어진 일만 트레이스에서 통째로 빠진 채 앞뒤는 멀쩡해 보여서, 트레이스를 열어 그 구간이 왜 비었는지 들여다보기 전까지 아무도 눈치채지 못합니다.

맺음말

얻은 건 명확합니다. 요청 하나에 id 하나가 서비스와 로그를 관통합니다. 로그에서 trace_id를 집어 트레이싱으로 넘어가면 전체 경로가 보이고, 서비스별로 따로 놀던 UUID를 맞춰보던 일이 없어졌습니다.

포기한 것과 남은 한계가 있습니다. 로그를 OTel 밖에 둔 대가로, 로그와 트레이스는 공통 id로만 이어져 있습니다. 한쪽에서 다른 쪽으로 id를 들고 건너가는 건 되지만, 한 곳에서 둘을 함께 질의하는 건 안 됩니다. 그리고 컨텍스트 전파는 제가 손댄 경로까지만 됩니다. 서블릿 요청과 TaskDecorator를 통한 async는 이었지만, 메시지 컨슈머나 스케줄러처럼 요청에서 시작하지 않는 자리, 헤더를 그대로 넘기지 않는 중간 지점이 있으면 거기서 trace_id가 끊깁니다. 자동 계측이 다 해줄 것 같지만, 손으로 스레드를 넘기거나 프로토콜을 갈아타는 자리는 결국 사람이 이어줘야 합니다.

span_id를 로그에 안 찍은 것도 언젠가 아쉬울 수 있습니다. 지금은 trace 단위로만 로그를 묶을 수 있고, 한 trace 안에서 어느 span이 남긴 로그인지는 로그만 봐선 모릅니다. 읽기 편하자고 뺐는데, 트레이스가 복잡해지면 다시 넣을 자리입니다.

실무, 운영 관측

서비스마다 자기 UUID를 찍고 있었다

trace_id로 바꾸니 요청이 서비스를 건너 이어졌다

로그는 OTel로 보내지 않았다

비동기로 넘어가면 트레이스가 끊겼다

맺음말

인기 태그