[Java] MDC 를 사용한 로그(Log)추적하기

회사에서 소스를 분석하면서 로그를 기록하는 것에 MDC 라는 것을 사용하고 있었다.

(새로운 회사에서 소스 분석하면서 모든게 새롭다... 기존에 내가 사용하던 것들은 어디에...)

간단하게 구글링해보니, 멀티쓰레드 환경에서 스레드 별로 ID를 할당시켜 로깅 추적할 때 원활하게 제공해주는 것이라고 한다고 하는데 이를 정리해보고자 한다.

---

1. MDC(Mapped Diagnostic Context)란?

- Map 형식을 이용하여 클라이언트 특징적인 데이터를 저장하기 위한 메커니즘.

- slf4j,logback,log4j2 등 Logger(로거)에서 MDC를 제공한다.

- MDC 는 key/value 저장소를 지원하며, 이 저장소는 ThreadContext 에 의존한다.

- MDC 클래스는 Map 안에 저장된 key 와 value 를 조작하기 위해 아래의 메소드들을 가진다.

• get(String key) : key 와 연관된 Value(데이터) 를 얻음
• put(String key, Object value) : key 와 연관된 Object(데이터) 를 저장
• remove(String key) : key 와 연관된 Value(데이터) 를 제거
• clear() : MDC의 항목을 지운다.

Logging 을 남길 때, 멀티쓰레드 환경에서 실행되는 task 는 로그가 섞여 제대로 확인하기 힘들다.
실행되는 Thread(쓰레드)마다 ThreadLocal 변수에 Id 값을 할당하여 실행 흐름을 추적(트래킹)할 수 있다.
하지만 매번 쓰레드에 Id를 주입해서 호출하는 것은 번거로운 작업인데 MDC 는 이 작업을 제공한다.

1-1. Thread Local

- Java 1.2 부터 제공.

- 쓰레드별로 Map 을 할당하고 값을 저장 관리 할 수 있다.(쓰레드별로 할당되는 것이 큰 특징)

- 특성상 쓰레드 단위로 어떠한 작업이 필요할 때 사용된다.

- MDC 가 ThreadLocal 을 사용한다.

- Thread Local 에 대한 자세한 내용은 아래 링크 블로그에 잘 정리되어 있으니 참고 부탁드립니다.

ThreadLocal 사용법과 활용

2. Example

2-0. MDC 적용 전

- 실제 운영하는 서비스에서 로그를 확인하다 보면 동시에 요청이 오는데, 이때 로그는 연속적으로 쌓이지 않고, 순서 없이 처리하는 대로 쌓이게 된다.

- 아래 그림과 같이 요청을 하였을 때, 하나의 로직 순서대로 쌓이지 않을뿐더러, 시작은 순차적일지라도 처리 도중에는 섞이게 된다.

- 현재 로그에서 시간 옆 부분은 쓰레드(Logback 설정, 아래 설정 참고)를 보여주도록 되어 있는데, 이 쓰레드는 처리하고 반환되고 하면서 같은 쓰레드를 사용할 수 있기 때문에 실제 트래킹 하기에는 어렵다.

- 이러한 문제를 해결하기 위해, MDC 를 사용하여 요청(Request)마다 고유 값을 할당하고, 로그에 출력하여 관리하고자 한다.

- Interceptor(인터셉터), Filter(필터), AOP 등 여러 방법을 통해서 사용할 수 있지만, 해당 글에서는 AOP를 통해서 예제를 구성해보겠습니다.

2-1. Dependency 추가

- logback, log4j, slf4j 를 통해 MDC를 사용할 수 있는데, 해당 글에서는 slf4j 를 사용하겠습니다.

- 아래 Dependency 를 추가합니다.

• Maven

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
    <version>2.4.4</version>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
    <version>2.4.4</version>
</dependency>

• Gradle

implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.springframework.boot:spring-boot-starter-aop'

참고!!!
기본적으로 MDC 라이브러리는 위 spring-boot-starter-web dependency에 포함되어 있습니다.
만약 포함되어 있지 않거나 사용하지 않는다면, 아래 dependenecy를 따로 추가해주시면 됩니다.

• Maven

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>

• Gradle

implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.36'

2-2. logback.xml 설정

- logback.xml 파일을 생성하여, 로그 출력 포맷을 설정합니다.

- 사용하고자 하는 임의의 변수(ex: traceId)를 아래와 같이 설정합니다.

• MDC.put 에 넣을 key 키 값을 아래와 같은 형식으로 사용합니다.
• 예를 들어, MDC.put("traceId", value) 라면, traceId를 출력하기 위하여 출력 포맷에 [traceId=%X{traceId}] 추가합니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" debug="false">
  
  <property name="console.format"
    value="* %-20(%cyan(%date{HH:mm:ss.SSS}) [%thread] [traceId=%X{traceId}]) %highlight(%-5level) %magenta(%marker|%logger{36}): %msg%n%rEx"/>

  <!-- console -->
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${console.format}</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="CONSOLE"/>
  </root>

</configuration>

2-3. AOP 설정

- Controller 를 통해 들어오는 Request/Response 를 AOP의 @Before, @AfrterReturning 으로 로깅 처리를 합니다.

- @Before 에서는 MDC에서 사용할 Trace ID 를 저장합니다.

• 이때 저장할 값은 UUID를 사용합니다.(고유 값을 가지는 값이면 무엇이든 괜찮습니다.)

- @AfterReturning, @AfterThrowing 에서는 MDC 를 초기화(Clear)합니다.

참고!!!
MDC 사용 시에는 주의할 점이 있는데, Response(@AfterReturning, @AfterThrowing) 시 clear를 해준다는 것이다.
Spring MVC는 쓰레드 풀(Thread Pool)에 쓰레드를 생성하여, 요청(Request)이 오면 쓰레드를 할당해 처리하고 반납합니다.
그러나 MDC는 쓰레드 별로 저장되는 Thread Local을 사용하고, 요청이 완료될 때 Clear 를 해주지 않는다면 다른 요청이 해당 쓰레드를 재사용할 때 이전 데이터가 남아있으면서 데이터에 혼동이 생길 수 있습니다.

@Slf4j
@Aspect
@Component
public class TestAspect {

    //	execution 뒤에는 컨트롤러 경로
    @Pointcut("execution(* com.study.slack.controller.*.*(..) )")
    public void controllerAdvice() {
    }

    @Before("controllerAdvice()")
    public void requestLogging(JoinPoint joinPoint) {

        // MDC TraceId 세팅
        MDC.put("traceId", UUID.randomUUID().toString());

        //log.info("REQUEST -> {}", joinPoint.getTarget());
        log.info("REQUEST TRACING_ID -> {}", MDC.get("traceId"));
    }

    @AfterReturning(pointcut = "controllerAdvice()", returning = "returnValue")
    public void requestLogging(JoinPoint joinPoint, Object returnValue) {

        //log.info("RESPONSE -> {}", joinPoint.getTarget());
        log.info("RESPONSE TRACING_ID -> {} / RESULT -> {}", MDC.get("traceId"), returnValue);

        // MDC Clear
        MDC.clear();
    }
}

2-4. Controller, Service

- 간단하게 요청받아서 처리하는 로직을 구성합니다.

• controller

@RestController
@RequiredArgsConstructor
@Slf4j
public class TestController {

    private final TestService testService;

    @GetMapping("/test")
    public String mdcTest(){
        log.info("Start Controller [TraceId] -> {}", MDC.get("traceId"));

        return testService.mdcTest();
    }
}

• service

@Slf4j
@Service
public class TestService {

    public String mdcTest() {
        log.info("Start Service [TraceId] -> {}", MDC.get("traceId"));

        return "MDC Logging Test";
    }
}

2-5. 테스트

- 간단하게 요청하여 테스트를 해보겠습니다.

- 아직 TraceId는 AOP를 통해서 controller를 요청할 때만 할당되기 때문에 서버가 올라오거나 controller를 요청하지 않는 작업에서는 위 그림과 같이 TraceId가 빈 값으로 할당되는 것을 확인하실 수 있습니다.

- Controller 를 요청하였을 때는, 아래 그림과 같이 동일 쓰레드(http-nio-8787-exec-6)지만, TraceId 가 다른 것을 확인할 수 있고, 이 TraceId로 트래킹을 하면 조금 더 편하게 로그 트래킹을 하실 수 있습니다.

---

참고

- https://mangkyu.tistory.com/266

- https://055055.tistory.com/96

- https://lucas-k.tistory.com/8

- https://javacan.tistory.com/entry/ThreadLocalUsage