트레이스 화면에서 응답하는 데 3초 넘게 걸린 주문 API 요청을 발견했습니다. 트레이스를 살펴보면 요청이 어떤 작업을 거쳤고, 각 작업에 시간이 얼마나 걸렸는지 확인할 수 있습니다. 하지만 느린 구간을 찾았다고 해서 그 이유까지 알 수 있는 것은 아닙니다. 어떤 값이 처리됐는지, 중간에 재시도나 예외가 있었는지 확인하려면 애플리케이션 로그를 함께 봐야 할 때가 있습니다.
그런데 막상 로그를 열어 보면 또 다른 문제가 생깁니다. 같은 시각에 처리된 수많은 요청의 로그가 뒤섞여 있기 때문입니다. 시각과 서버 이름으로 범위를 좁혀도, 어느 로그가 문제의 주문 요청에서 나온 것인지 구분하기는 쉽지 않습니다.
로그와 트레이스 연결은 로그 한 줄마다 그 로그를 남긴 요청의 트레이스 식별자(trace_id)를 함께 기록하는 일입니다. 영어로는 log trace correlation이라고 하고, 로그와 트레이스 상관관계, 줄여서 로그 상관관계라고도 부릅니다.
로그에 trace_id가 남아 있으면 앞에서 발견한 주문 요청의 trace_id로 관련 로그를 검색할 수 있습니다. 주문 요청이 거친 주문 서비스와 결제 서비스의 로그를 시각순으로 보며 단서를 찾는 것입니다. 반대로 에러 로그에 찍힌 trace_id로 그 요청의 트레이스를 열 수도 있습니다. 이 글은 로그에 trace_id가 이미 남아 있다고 보고 trace_id의 역할과 그 값으로 로그를 찾는 순서를 정리합니다. trace_id를 로그에 출력하도록 설정하는 방법은 다음 글에서 다룹니다.
분산 추적(distributed tracing)은 요청 하나가 여러 서비스를 거치는 경로를 기록하는 방식입니다. 이때 요청 하나의 전체 경로를 트레이스(trace)라고 부르고, 그 안의 작업 단위 하나하나를 스팬(span)이라고 부릅니다. 주문 서비스가 받은 HTTP 요청, 주문 서비스가 결제 서비스를 부른 호출, 결제 서비스가 그 호출을 받아 처리한 작업, 결제 서비스가 실행한 DB 쿼리가 각각 스팬입니다.
trace_id는 트레이스 전체에 하나만 붙는 값입니다. 주문 서비스의 작업과 결제 서비스의 작업은 같은 요청에 속하므로, 요청이 주문 서비스에서 결제 서비스로 넘어가도 trace_id는 그대로입니다. span_id는 스팬마다 새로 만들어집니다. HTTP 요청 처리, 결제 서비스 호출, 결제 요청 처리, DB 쿼리는 서로 다른 작업이라 span_id가 각각 다릅니다.
로그에 두 값을 함께 남기면 trace_id로는 같은 요청의 로그를 모으고, span_id로는 그 요청의 어느 작업에서 남긴 로그인지 구분할 수 있습니다.
trace_id가 요청 전체에서 같은 값으로 유지되려면, 서비스가 다음 서비스를 호출할 때 그 값을 함께 넘겨야 합니다. 서로 다른 언어로 만든 서비스끼리도 같은 trace_id를 주고받을 수 있도록 헤더 형식을 정한 표준이 W3C Trace Context입니다. 이 표준은 값을 실어 보낼 HTTP 헤더로 traceparent를 정했습니다. HTTP 헤더는 요청 본문과 함께 보내는 부가 정보이고, traceparent에는 trace_id와 호출한 쪽의 span_id가 들어갑니다.
traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01맨 앞 00은 형식 버전이고, 다음 32자리는 trace_id입니다. 이어지는 16자리는 표준에서 parent-id라고 부르는 값으로, 호출한 쪽 스팬의 span_id입니다. 마지막 01은 호출한 쪽이 이 요청을 트레이스로 기록할 대상으로 표시했다는 뜻입니다. 모든 요청을 기록하지 않고 일부만 골라 기록하는 방식을 샘플링이라고 하며, 아래 자주 묻는 질문에서 다시 다룹니다.
아래 도식은 지금까지 설명한 trace_id, span_id, traceparent를 앞의 주문 서비스와 결제 서비스 예시 하나에 모아 트레이스 화면처럼 그린 것입니다. 가로는 시간이고, 한 단계 들여 쓴 막대는 바로 위 막대가 실행되는 동안 일어난 작업입니다.

trace_id처럼 여러 서비스의 로그를 하나로 모으는 데 쓰는 값으로 correlation id도 있습니다. trace_id보다 먼저 쓰이던 값입니다. 두 값 모두 같은 요청을 가려내는 데 쓸 수 있지만, trace_id는 트레이스의 스팬 구조와 연결된다는 점이 다릅니다.
correlation id 방식에서는 게이트웨이나 첫 서비스가 요청을 받을 때 UUID 같은 값을 하나 만들고, X-Request-ID나 X-Correlation-ID 같은 헤더에 실어 다음 서비스로 넘깁니다. 각 서비스는 그 헤더를 읽어 로그에 남기는데, 이 코드는 팀이 직접 작성하는 경우가 많습니다.
correlation id로도 같은 요청의 로그는 모을 수 있지만, 호출 순서와 단계별 소요 시간은 로그 시각을 비교해 추정해야 합니다. trace_id를 쓰면 같은 값으로 트레이스 화면을 열어 바로 확인할 수 있습니다.
trace_id가 중간에 끊기는 경로에서는 다른 식별자를 함께 남겨 둡니다. 예를 들어 주문 서비스가 결제 메시지를 메시지 큐에 넣고, 결제 서비스가 나중에 그 메시지를 꺼내 처리한다고 가정해 보겠습니다. 메시지 큐는 처리할 메시지를 잠시 저장해 두었다가 다른 서비스에 넘겨주는 중간 저장소입니다. 메시지 큐를 거치면 계측 방식(트레이싱 라이브러리가 메시지에 trace_id를 함께 싣는지)에 따라 trace_id가 결제 서비스까지 이어지지 않을 수 있고, 그러면 주문과 결제가 서로 다른 트레이스로 기록됩니다. 이럴 때 주문 번호 같은 업무 식별자나 따로 넘기는 correlation id를 로그에 함께 남겨 두면, 트레이스가 달라도 같은 주문의 로그를 모아 볼 수 있습니다.
Spring Boot를 쓴다면 문서에서 correlation ID라는 말을 보게 됩니다. Spring Boot 문서는 로그에 찍히는 [traceId-spanId] 묶음을 correlation ID라고 부릅니다. 이 correlation ID는 팀이 만드는 별도 값이 아니라 trace_id와 span_id를 붙여 쓴 표기입니다.
로그에 trace_id가 들어가 있으면 장애를 처음 발견한 곳에 따라 두 방향으로 찾을 수 있습니다. 메트릭과 로그, 트레이스를 어떤 순서로 보는지는 장애 분석 시간을 줄이는 옵저버빌리티 메트릭 로그 트레이스 분석 순서에서 사례로 다뤘습니다.
트레이스에서 로그로 응답이 느리거나 실패한 요청을 트레이스 화면에서 먼저 찾은 경우입니다.
로그에서 트레이스로 에러 로그를 먼저 봤거나 알림을 받은 경우입니다.
trace_id로 검색했는데 특정 서비스의 로그만 보이지 않는다면, 먼저 그 서비스가 로그에 trace_id를 기록하고 있는지와 로그가 제대로 수집됐는지 점검합니다. 둘 다 문제가 없다면 앞 서비스가 호출할 때 traceparent 헤더를 넘기는지 살펴봅니다. 헤더가 빠지면 뒤 서비스는 새 trace_id로 로그를 남깁니다. Spring Boot라면 HTTP 클라이언트를 직접 생성한 경우가 대표적입니다. Spring Boot가 미리 만들어 주는 RestTemplateBuilder, RestClient.Builder, WebClient.Builder로 만들어야 헤더를 넣는 트레이싱 설정이 함께 적용됩니다.
기동 로그나 배치 작업 로그처럼 요청과 무관하게 남는 로그에는 trace_id가 없으니, 시각과 호스트, 스레드 이름으로 범위를 줄여 찾습니다.
trace_id가 아예 비어 있거나 다른 요청의 값이 찍힌다면 로깅 설정이나 trace_id를 직접 넣는 코드부터 점검합니다. 증상별 원인은 다음 글에서 표로 정리합니다.
trace_id로 요청 하나의 로그를 찾으려면 각 서비스가 로그에 trace_id를 남기고 그 로그를 수집해야 하며, 서비스 사이에서는 traceparent 헤더로 같은 값을 넘겨야 합니다. 이 조건이 갖춰지면 trace_id 하나로 트레이스 화면의 느린 요청에서 로그로, 에러 로그에서 그 요청의 트레이스로 오갈 수 있습니다. 특정 서비스의 로그만 빠져 있다면 trace_id 기록, 로그 수집, 헤더 전달 순서로 따라가 봅니다. 로그에 trace_id를 넣는 설정과 비동기 작업에서 값이 빠지는 문제는 이어지는 글의 주제입니다.
로그에 표준 trace_id 대신 자체 식별자를 남겨 같은 목적을 이루는 APM 제품도 있고, 와탭도 그중 하나입니다. 와탭 APM의 Java, Python, Node.js 에이전트는 로그에 트랜잭션 아이디(txid)를 함께 남겨, 와탭 로그 모니터링에서 트랜잭션에 연결된 로그를 볼 수 있게 합니다. Java와 Python 에이전트를 쓰면 로그 검색에서 로그 한 줄을 골라 그 트랜잭션 정보로 이동할 수도 있고, 여러 서비스를 거친 요청을 묶는 멀티 트랜잭션 아이디(mtid)도 로그에 남길 수 있습니다. 두 아이디는 trace_id와 같은 값이 아니라, 분산 추적 개념과 역할이 대응하는 값입니다.
언어별 지원 범위와 로그 연동 설정은 Java, Python, Node.js 로그 모니터링 문서에서 확인할 수 있습니다.
W3C Trace Context 기준으로 trace_id는 16바이트 값을 소문자 16진수 32자리로, span_id는 8바이트 값을 16자리로 씁니다. 표준은 모든 자리가 0인 값을 유효하지 않은 값으로 봅니다. 일부 도구는 대문자로 표시하거나 자체 형식으로 바꿔 저장하기도 해서, 같은 값인데 검색이 안 된다면 대소문자와 자릿수부터 맞춰 봅니다.
트레이싱 도구가 그 요청을 샘플링하지 않아 트레이스가 저장되지 않았을 가능성이 큽니다. 샘플링은 저장 비용을 줄이려고 일부 요청만 트레이스로 기록하는 방식으로, Spring Boot는 기본으로 요청의 10%만 샘플링합니다.
트레이스가 저장되지 않았어도 로그에 trace_id가 기록되고 수집됐다면, 같은 trace_id로 여러 서비스의 로그를 요청 단위로 모아 볼 수 있습니다. 트레이스 화면에서만 찾을 수 없을 뿐입니다.
OpenTelemetry는 Trace Flags라는 값으로 각 스팬의 샘플링 여부를 표시하고, OpenTelemetry Java 에이전트는 이 값을 trace_flags라는 키로 로그에 넣습니다. 이 값은 traceparent 헤더 마지막 두 자리와 같아서, 01은 샘플링 대상, 00은 대상이 아니라는 뜻입니다. 로그에 trace_flags도 함께 출력해 두면 트레이스가 없을 가능성이 큰 로그를 구분할 수 있습니다. 다만 수집 단계에서 한 번 더 거르는 설정도 있어서, trace_flags만으로 트레이스가 실제로 저장됐는지까지 확정할 수는 없습니다.