MDC, TaskDecorator 를 이용해서 비동기 쓰레드에서 로깅하기

개발을 할 때 로그를 보기 쉽게 하기위해서 로그앞에 UUID를 넣는 개발자들이 대부분일 것이다.

 

하지만, @Async와 같은 비동기 스레드에서는 메인스레드에 저장된 UUID를 출력하기 힘들다.

 

아래 사진과 같이 말이다.

 

위와 같은 문제를 MDC, TaskDecorator를 이용하여 해결하고자 한다.

 

 

MDC

MDC(Mapped Diagnostic Context)는 자바 로깅 프레임워크(slf4j 등)에서 지원하는, 현재 실행중인 쓰레드 단위에 메타 정보를 넣고 관리하는 공간(ThreadLocal)이다. MDC 안에는 UUID뿐만 아니라 다른 메타정보를 보관 할 수 있다.

 

주의할점
ThreadLocal 특성상 Thread안에서 MDC로 어떤 값을 할당 하면 Thread가 종료되기 전까지 해당 값이 계속 저장되어 있기 때문에 사용을 다 했다면 반드시 clear()를 호출해줘야 한다는 점이다. clear를 하지 않는다면 나중에 어떤문제가 발생할지 모름!!

 

사용방법은 간단하다

@Test
void MDCTest() {
    MDC.put("uuid", UUID.randomUUID().toString());

    // 로직...

    String uuid = MDC.get("uuid");
    System.out.println("uuid = " + uuid);
}

출력--
uuid = dd1a12d0-130e-4f30-b2ae-b0e5782c1197

 

위와 같이 저장할 데이터를 MDC.put 으로 넣어주고 사용할때는 MDC.get으로 사용하면 된다.

 

 

TaskDecorator

TaskDecorator는 Spring AOP을 사용하는 것과 처럼 ThreadPoolTaskExecutor에 의해 관리되는 쓰레드가 매번 사용될 때마다 실행 전후에 끼어들어 동작을 제어할 수 있다.

 

조금있다가 사용될 코드를 미리 봐보자!!

 

TaskDecorator

public class MDCCopyTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> contextMap = MDC.getCopyOfContextMap();
        return () -> {
            try {
                if (contextMap != null) {	// 스레드 실행되기전 실행할 코드
                    MDC.setContextMap(contextMap);
                }
                runnable.run(); // 실제 스레드에서 실행되어야할 코드
            } finally {
                MDC.clear();	// 스레드 실행완료후 실행할 코드
            }
        };
    }
}

 

 

AsyncConfiguration

@Bean
public ThreadPoolTaskExecutor asyncThreadPoolTaskExecutor() {
    ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
    taskExecutor.setCorePoolSize(5);    //생성해서 사용할 스레드 풀에 속한 기본 스레드 갯수(default : 1)
    taskExecutor.setMaxPoolSize(10);    //최대 스레드 갯수 (default : Integer.MAX_VALUE (약 21억))
    taskExecutor.setQueueCapacity(20);  //이벤트 대기 큐 크기 (default : Integer.MAX_VALUE (약 21억))
    taskExecutor.setThreadNamePrefix("Async-");
    taskExecutor.setTaskDecorator(new MDCCopyTaskDecorator());// 기존 스레드의 로그키값이 담긴 MDC request_id 정보가 Async 스레드에서 수행될 스레드의 MDC 안에 복제한다.
    return taskExecutor;
}

 

 

위 코드와 같이 setTaskDecorator로 세팅 해주면 asyncThreadPoolTaskExecutor가 사용 될때 마다 MDCCopyTaskDecorator에 만든 코드가 실행 될 것이다.

 

 

비동기 쓰레드 로깅 처리하기 - 1

이제 MDC와 TaskDecorator로 비동기 쓰레드 로깅을 해보자.

 

핵심 코드는 위에서 봤던 코드이다.

 

 

TaskDecorator

public class MDCCopyTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> contextMap = MDC.getCopyOfContextMap();
        return () -> {
            try {
                if (contextMap != null) {	// 스레드 실행되기전 실행할 코드
                    MDC.setContextMap(contextMap);
                }
                runnable.run(); // 실제 스레드에서 실행되어야할 코드
            } finally {
                MDC.clear();	// 스레드 실행완료후 실행할 코드
            }
        };
    }
}

 

 

AsyncConfiguration

@Bean
public ThreadPoolTaskExecutor asyncThreadPoolTaskExecutor() {
    ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
    taskExecutor.setCorePoolSize(5);    //생성해서 사용할 스레드 풀에 속한 기본 스레드 갯수(default : 1)
    taskExecutor.setMaxPoolSize(10);    //최대 스레드 갯수 (default : Integer.MAX_VALUE (약 21억))
    taskExecutor.setQueueCapacity(20);  //이벤트 대기 큐 크기 (default : Integer.MAX_VALUE (약 21억))
    taskExecutor.setThreadNamePrefix("Async-");
    taskExecutor.setTaskDecorator(new MDCCopyTaskDecorator());// 기존 스레드의 로그키값이 담긴 MDC request_id 정보가 Async 스레드에서 수행될 스레드의 MDC 안에 복제한다.
    return taskExecutor;
}

 

 

MDCCopyTaskDecorator에서 TaskDecoator를 implements 받아서 decorate를 구현하면 된다.

위 소스처럼 runnable.run() 위 아래로 실제 스레드에서 실행되어야할 코드 전/후에 데코레이터를 할 수 있다.

중요하게 봐야할 부분은 MDC.getCopyContextMap()이다. 이 메서드는 해당 스레드 MDC에 저장되어있는 데이터를 복사한다. 그리고 실행되어야할 쓰레드 MDC에 복사해 넣는다. 그렇게 되면 다른 스레드에서도 사용할수 있게 된다.

AsnycConfiguration에서는 ThreadPoolTaskExecutor를 생성 해주었다. 그리고 반드시 우리가 만든 MDCCopyTaskDecorator를 set해주면 준비 끝!

 

그리고 MDC에서 put한 값을 로그에 출력하기 위해서 application.yml에 pattern을 등록해야한다.

맨 앞부분에 [%X{request_id:----}] 부분에 주목하자! MDC.put("request_id", uuid) 로 등록하게 되면 콘솔 로그에서 해당 값을 출력해준다! 만약에 없다면 ---가 출력될 것이다.

spring:
 pattern:
  console: "[%X{request_id:----}]%clr(%d{${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd'T'HH:mm:ss.SSSXXX}}){faint} %clr(${LOG_LEVEL_PATTERN:%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:%wEx}"

 

 

 

비동기 쓰레드 로깅 처리하기 - 2

MDCCopyTaskDecorator가 없는 상태로 아래 테스트 코드를 돌려보자

 

AsyncConfiguration

@Configuration
public class AsyncConfiguration {

    @Bean
    public ThreadPoolTaskExecutor asyncThreadPoolTaskExecutor() {
        ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
        taskExecutor.setCorePoolSize(5);    //생성해서 사용할 스레드 풀에 속한 기본 스레드 갯수(default : 1)
        taskExecutor.setMaxPoolSize(10);    //최대 스레드 갯수 (default : Integer.MAX_VALUE (약 21억))
        taskExecutor.setQueueCapacity(20);  //이벤트 대기 큐 크기 (default : Integer.MAX_VALUE (약 21억))
        taskExecutor.setThreadNamePrefix("Async-");
//        taskExecutor.setTaskDecorator(new MDCCopyTaskDecorator());// 기존 스레드의 로그키값이 담긴 MDC request_id 정보가 Async 스레드에서 수행될 스레드의 MDC 안에 복제한다.
        return taskExecutor;
    }
}

 

 

TestService

@Slf4j
@Service
public class TestService {

    @Async("asyncThreadPoolTaskExecutor")
    public void test(int index) {
        log.info("test" + index);
    }
}

 

 

TestCode

@SpringBootTest
@Import(AsyncConfiguration.class)
public class MyTest {

    @Autowired
    TestService testService;
    @Test
    void asyncTest() throws InterruptedException {

        MDC.put("request_id", UUID.randomUUID().toString());

        for (int i = 0 ; i < 10 ; i++) {
            testService.test(i);
        }
        Thread.sleep(1000);

        MDC.clear();
    }
}

 

결과

위 사진과 같이 MDC에 key가 request_id인 값이 없기때문에 ---가 출력 되는것을 볼수 있다.

 

 

 

비동기 쓰레드 로깅 처리하기 - 3

다시 MDCCopyTaskDecorator를 주석 해제하고 돌려보자

 

AsyncConfiguration

@Configuration
public class AsyncConfiguration {

    @Bean
    public ThreadPoolTaskExecutor asyncThreadPoolTaskExecutor() {
        ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
        taskExecutor.setCorePoolSize(5);    //생성해서 사용할 스레드 풀에 속한 기본 스레드 갯수(default : 1)
        taskExecutor.setMaxPoolSize(10);    //최대 스레드 갯수 (default : Integer.MAX_VALUE (약 21억))
        taskExecutor.setQueueCapacity(20);  //이벤트 대기 큐 크기 (default : Integer.MAX_VALUE (약 21억))
        taskExecutor.setThreadNamePrefix("Async-");
        taskExecutor.setTaskDecorator(new MDCCopyTaskDecorator());// 기존 스레드의 로그키값이 담긴 MDC request_id 정보가 Async 스레드에서 수행될 스레드의 MDC 안에 복제한다.
        return taskExecutor;
    }
}

 

 

결과

위와 같이 비동기 쓰래드 로그에서도 UUID를 출력할 수 있게 된다!!

 

 

 

 

Reference

https://techblog.woowahan.com/13429/

로그 및 SQL 진입점 정보 추가 여정 | 우아한형제들 기술블로그

https://velog.io/@tritny6516/Spring-Logging-with-MDC

Spring Logging with MDC

https://jsonobject.tistory.com/468

Spring Boot, 비동기 쓰레드에서 호출 쓰레드의 MDC 보존하기