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

게시 2026/01/15

By 영킴 12 분 읽는 시간

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

한 요청을 여러 서비스가 나눠 처리하는 구조입니다. 셀러용 API가 요청을 받으면 회원·정산 쪽으로 내부 호출이 이어집니다. 문제 하나를 쫓을 때 이 서비스 저 서비스 로그를 오가야 하는데, 그걸 하나로 묶어줄 공통 ID가 없었습니다. 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이 남긴 로그인지는 로그만 봐선 모릅니다. 읽기 편하자고 뺐는데, 트레이스가 복잡해지면 다시 넣을 자리입니다.

Framework, SpringBoot

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

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

로그는 OTel로 보내지 않았다

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

맺음말

인기 태그