[Spring] MDC, 로그 트레이싱하기

오늘은 MDC(Mapped Diagnostic Context)에 대해서 공부한 내용을 기록하려고 한다.

 

공부하게 된 계기

갑자기 MDC에 대해서 공부하게 된 계기는요,

회사에서 업무를 하다 보니, 실제 개발하는 시간만큼 민원을 처리하는 날들이 많았다. 기존 코드를 이해하는 것보다는 민원을 처리해야 하는 일이 그 업무 프로세스를 완전히 이해해야 하고 있어야 하며 로그를 확인하고 원인을 파악하는 일이라 신입인 나에게 아직 낯선 작업들이었다.

 

민원을 처리하기 위해 로그 혹은 와탭(Whatap)을 확인 하는 경우가 있는데, 대부분 전문 기록을 확인해야 하는 경우가 많아 로그를 확인한다. 로그를 확인하는 과정을 간단하게 나열하면 다음과 같다.

• 민원이 발생한 부분의 소스 코드를 찾아 어떤 전문을 사용하는지 찾기
• 메타 시스템에서 해당 전문의 요청/응답 값에 회원의 어떤 정보가 포함되어 전달하는지 파악 (전문번호, 회원번호 ..)
• 해당 정보를 바탕으로 grep 하여, 한 파일 내에 로그 뽑아내기
• 요청 일련번호 단위로 로그 트레이싱 하기
• 전문 요청/응답 값 파싱하여 원인 파악하기

이 과정에서 등장하는 "요청 일련번호 단위" 개념이 바로 MDC이다.

 

대부분의 웹 서비스는 멀티 쓰레드 환경에서 동작하며, 여러 요청을 동시에 처리하기 때문에 동일한 요청에 대한 로그가 연속적으로 쌓이는 것은 불가능하다. 아래는 마이브러리 서비스의 로그가 CloudWatch에 찍히는 것을 캡처해 온 것인데, 로그를 요청 단위로 마지막에 한번 찍기 때문에.. MDC를 확인하기는 적합하지 않은 것 같다.. 

 

실무에는 위 예시와는 차원이 다르게 매우 많은 내용들을 로그로 남긴다... (마이브러리 서비스에도 로그를 많이 추가해야겠다..)

 

예전에 김영한 님의 AOP 강의를 들으면서 작성했던 코드를 동작시킨 로그를 가져와봤다!

 

요청 별로 로그를 확인해야 하는데, 로그가 순서대로 찍히지 않고 뒤섞여 있기 때문에 문제가 발생했을 대 원인을 추적하고 진단하기 어렵다. 이런 문제를 해결하기 위해 로그와 함께 특정 요청에 대한 로그들을 하나로 묶을 수 있어야 한다.

 

이때 사용하는 것이 MDC (Mapped Diagnostics Context)이다.

 

MDC (Mapped Diagnostic Context)

• 현재 실행 중인 쓰레드에 메타 정보를 넣고 관리하는 공간
• 내부적으로 Map으로 관리하고 있어 (Key, Value) 형태로 값을 저장할 수 있다.
• 메타 정보를 쓰레드 별로 관리하기 위해서 내부적으로 쓰레드 로컬을 사용하고 있다.
• 그리고 UUID로 로그를 찾으면 1개의 요청에 대한 로그를 살펴볼 수 있다.
• Slf4j, logback 등 많은 Logger에서 MDC를 제공한다.

 

* 쓰레드 로컬 : 해당 쓰레드만 접근할 수 있는 저장소. 각 쓰레드마다 별도의 내부 저장소를 제공

실제 MDC 클래스를 타고 타고 들어 가면, MDCAdapter Interface를 사용하는 데, 구현체 중 BasicMDCAdapter 를 보면 아래와 같이 ThreadLocal 을 활용하고 있음을 확인 할 수 있다.

 

MDC 적용하기

slf4j에서 MDC 기능을 제공하기 때문에 아래와 같이 slf4j 를 사용하여 적용가능하다.

MDC에 Context Id를 저장할 위치는 필터, 인터셉터 등이 있을 텐데 그중에서 가장 요청을 먼저 마주하는 필터에 적용하는 것이 적합하다고 생각한다. 아래와 같이 필터를 구현할 수 있다.

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MDCFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
            throws IOException, ServletException {

        final UUID uuid = UUID.randomUUID();
        MDC.put("context_id", uuid.toString());
        chain.doFilter(request, response);
        MDC.clear();

    }
}

 

• @Order(Ordered.HIGHEST_PRECEDENCE)를 통해 가장 높은 우선순위를 부여한다.
• MDC.clear()는 필수적이다. Spring MVC는 쓰레드 풀을 만들어 두고, 요청이 오면 쓰레드를 사용해 요청을 처리하고 반납하는 구조이다. MDC는 쓰레드 별로 저장되는 쓰레드 로컬을 사용하기 때문에 Clear을 하지 않으면, 다른 요청이 이 쓰레드를 재사용할 때 이전 데이터가 남아 있을 수도 있기 때문이다.

 

모든 로그에 아래 코드와 같이 사용하면, MDC에 저장한 uuid 값을 가져올 수 있다.

log.info("[{}] {}{}", MDC.get("context_id"), addSpace(START_PREFIX, traceId.getLevel()), message);

 

위와 같이 uuid를 통해서 요청 단위로 구분이 가능하다 👍🏻

 

하지만 위와 같은 방법은 로그를 찍는 부분에 MDC.get("context_id")를 작성해야 하기 때문에, 번거롭기도 하고 누락되기 쉽다. 그래서 Logback 설정을 통해서 모든 로그에 글로벌하게 적용할 수 있다.

 

- logback.xml

<configuration>
  <appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>[%d{yyyy.MM.dd HH:mm:ss.SSS}] - [%level] - [%X{context_id}] - %msg%n</pattern>
    </encoder>
  </appender>
  
  <root level="info">
    <appender-ref ref="consoleAppender"/>
  </root>
</configuration>

 

- logback 설정 후 결과

 

 

 

 

참고 레퍼런스

https://hudi.blog/slf4j-mapped-diagnotics-context/

https://mangkyu.tistory.com/266

https://dev-jwblog.tistory.com/126