← 개발 로그 목록

website: 요청추적 ID(requestId) 도입

/ 7분 분량 / 개발 로그
#website#requestId#MDC#로깅#SpringSecurity

한 요청이 여러 로그 줄에 걸칠 때 그 줄들을 하나로 묶어볼 방법이 없어서, 요청마다 UUID를 발급해 로그에 자동으로 붙이는 작업을 했다.

#313에서 운영 원인추적용 로깅을 붙여둔 뒤로, 정작 사고가 나면 "이 에러가 어느 요청에서 났는지"를 로그 앞뒤 줄을 눈으로 짐작하며 찾고 있었다. 서비스 로그 한 줄, 에러 로그 한 줄이 같은 요청에서 나온 건지 확인할 방법이 없었던 거다. RequestIdFilter를 만들어서 요청이 들어올 때마다 UUID를 발급해 SLF4J MDC에 심고, application.yml의 logging.pattern.level에 [reqId=%X{requestId}]를 얹었다. 전체 로그 패턴을 새로 정의하는 대신 Spring Boot 기본 패턴 위에 최소한만 추가하는 쪽을 택했다.

클라이언트가 보낸 값은 신뢰하지 않고 항상 서버에서 새로 발급하기로 했다. 대신 응답 헤더 X-Request-Id로 돌려줘서, FE나 QA가 "이 요청이 서버 로그에서 어떤 requestId였는지"를 알 수 있게 했다. 필터는 @Order(HIGHEST_PRECEDENCE)로 Spring Security 필터 체인보다 먼저 실행되게 했는데, 그래야 로그인 검증 같은 그 안의 필터들이 남기는 로그에도 이 ID가 붙는다.

@Async 구간까지 이어붙이기

MDC는 스레드 로컬이라 @Async가 작업을 다른 스레드로 넘기면 그 스레드엔 requestId가 없는 채로 시작한다. 처음엔 이걸 각 @Async 메서드마다 따로 처리해야 하나 싶었는데, TaskDecorator 빈을 하나 등록하면 Spring Boot가 @EnableAsync용으로 자동 생성하는 스레드풀에 자동으로 적용된다는 걸 확인했다(TaskExecutionAutoConfiguration가 감지). 그래서 MdcTaskDecorator 하나만 만들었더니 프로젝트의 모든 @Async(RecruitmentOpenEmailEventListener, EmailLogEventListener)에 별도 설정 없이 한 번에 적용됐다.

이걸 만들면서 모집 열기 → 구독자 전원 이메일 발송 흐름을 실제 코드로 따라가봤다. "이메일마다 스레드가 새로 생기는" 구조일 거라 생각했는데, 확인해보니 "요청 스레드 → 발송 담당 스레드 하나"로 딱 한 번만 스레드가 바뀌고 그 안에서 forEach로 순차 발송하는 구조였다. 그래서 원본 요청의 requestId 하나만 그 스레드에 이어 붙이면 됐고, 구독자 100명한테 보내는 로그 100줄이 전부 같은 requestId를 달게 된다 — 이건 "이 100통이 같은 모집 열기 요청 하나에서 나왔다"는 걸 보여주는 의도된 동작이다.

/error 재전송에서 requestId가 빠지던 버그

여기까지 하고 리뷰(Copilot)에서 발견된 문제가 있었다. 서버에서 예상 못한 에러가 나서 로그를 남기는 바로 그 순간에 requestId가 빠져 있었다. 다른 정상 요청 로그엔 다 붙는데, 하필 제일 중요한 "버그 발생" 로그에만 안 붙는 상황이었다.

원인을 따라가보니 이랬다. 컨트롤러에서 아무도 처리 못 한 예외(NPE 같은 것)가 터지면 톰캣이 그걸 감지해서 /error라는 특별한 경로로 요청을 다시 흘려보낸다(forward). 그리고 이전에 만들어둔 LoggingErrorAttributes가 이 재전송을 통해 도착한 요청을 받아서 최종 로그를 남긴다. 문제는 RequestIdFilter를 만들 때 쓴 OncePerRequestFilter가 기본적으로 이 두 번째 통과(에러로 인한 재전송)를 건너뛰도록 설정돼 있었다는 점이다. 그래서 1차 통과 때 발급한 requestId가 컨트롤러 실행까지는 붙지만, 에러가 나서 /error로 재전송되는 2차 통과에서는 필터 자체가 스킵되면서 번호 없는 채로 LoggingErrorAttributes가 로그를 남기고 있었다.

고친 방법은 두 가지였다. shouldNotFilterErrorDispatch()를 false로 바꿔서 두 번째 통과도 건너뛰지 않게 했고, 다만 그냥 실행만 하면 2차 통과 때 새 번호를 발급해버려서 1차와 달라질 수 있었다. 그래서 1차에서 발급한 번호를 request attribute(요청 객체에 붙이는 꼬리표, MDC와 달리 forward에도 그대로 남아있다)에 메모해뒀다가 있으면 재사용하도록 했다.

String requestId = (String) request.getAttribute(REQUEST_ATTRIBUTE);
if (requestId == null) {
    requestId = UUID.randomUUID().toString();
    request.setAttribute(REQUEST_ATTRIBUTE, requestId);
}
MDC.put(MDC_KEY, requestId);

이걸 테스트로 증명하는 게 생각보다 까다로웠다. MockMvc(가짜 서블릿 환경)로는 이 "재전송" 자체가 재현이 안 됐다 — 진짜 톰캣 컨테이너 레벨의 동작이라 흉내만 내는 환경에선 안 걸린다. 그래서 webEnvironment=RANDOM_PORT로 진짜 내장 서버를 띄우고 실제 HTTP 요청을 보내는 방식으로 다시 짰다. 로그백의 ListAppender를 붙여서 실제로 찍히는 에러 로그를 가로챈 다음, 그 로그의 MDC 값과 응답 헤더의 requestId가 같은지 끝까지 확인하는 테스트(RequestIdErrorDispatchTest)를 만들었다.

곁들여 확인한 것

이 작업 중에 "구독자 순차 발송을 병렬화하면 더 빠르지 않냐"는 얘기가 나와서, 실제로 막는 제약이 있는지 확인해봤다. SQLite의 HikariCP maximum-pool-size: 1 제약은 email_log DB 쓰기 단계만 막을 뿐 SMTP 발송 자체(외부 네트워크 호출)는 DB 커넥션과 무관해서 병렬로 겹칠 수 있었고, OCI Email Delivery의 발송 속도 제한도 이 프로젝트 계정(PAYG)은 분당 18,000통까지 허용돼서 병목이 아니었다. 즉 병렬화를 막는 실제 제약은 없고 지금 순차인 건 단순 구현 선택으로 보였다(코드에 근거 주석도 없었다). 이번 PR 스코프는 아니라서 backend/docs/email-module.md에 조사 결과만 기록해뒀다.

PR이 병합된 뒤에는 infra/docs/logging.md와 RUNBOOK.md에 X-Request-Id로 버그 리포트를 정확히 매칭하는 워크플로도 문서화했다. 브라우저 개발자도구에서 X-Request-Id 헤더를 복사해 버그 리포트에 포함시키면 그 값으로 로그 파일을 grep해서 정확히 그 요청의 로그 줄만 찾을 수 있다는 내용인데, 아직 팀이 실제로 이렇게 리포트하는 습관은 없다는 점과 Security가 401/403으로 끝내는 요청은 헤더는 붙지만 대응하는 로그 줄 자체가 없어 지금은 매칭할 게 없다는 한계도 같이 적어뒀다.