포스트

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

게시
By 영킴 11 분 읽는 시간

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

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

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

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

1
2
3

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

1

[%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를 꺼내는 걸로 바꿨습니다.

1
2
3
4
5
6
7

// 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());
}

1

[%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로 콜렉터에 실려 갑니다. 처음엔 이것도 켰습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

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까지 붙이면 같은 로그가 두 갈래로 나가고, 수집·저장 비용만 두 배가 됩니다. 로그와 트레이스를 잇는 건 로그 줄에 찍힌 trace_id 하나면 되지, 로그 본문 자체를 트레이스와 같은 파이프로 실어 보낼 이유가 없었거든요. 그래서 appender를 도로 껐고, 쓰지도 않는 로그 익스포터 설정도 지웠습니다. OTel로는 트레이스와 메트릭만 내보냅니다.

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

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

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

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

1
2
3
4
5
6
7
8
9
10
11
12
13

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 안에서 벌어진 일만 트레이스에서 빠지고 앞뒤는 멀쩡해 보여서, 그 구간이 왜 비었는지 들여다보기 전까지 아무도 모릅니다.

위 데코레이터는 작업이 끝나도 MDC를 비우지 않습니다. 요청 밖에서 들어온 작업이면 같은 풀 스레드에 남아 있던 이전 trace_id가 찍힐 수 있습니다. 회원 서비스에는 같은 날 finally에서 비우는 처리를 넣었는데, 셀러용 API 쪽은 아직 그대로입니다.

컨슈머와 스케줄러에서는 아직 끊긴다

컨텍스트 전파는 제가 손댄 경로까지만 됩니다. 서블릿 요청과 TaskDecorator를 통한 async는 이었지만, 메시지 컨슈머나 스케줄러처럼 요청에서 시작하지 않는 자리, 헤더를 그대로 넘기지 않는 중간 지점이 있으면 거기서 trace_id가 끊깁니다.

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

실무, 운영 관측
springboot spring isms 회고
이 기사는 저작권자의 CC BY 4.0 라이센스를 따릅니다.