배경
강남언니 서비스에서는 슬랙 모니터링을 많이 활용하고 있습니다. 그런데 보통의 오류 메시지를 핸들링할때와는 달리, 비동기 태스크를 수행 중에 오류가 나오면 아래와 같이 요청 URL 이나 사용자정보 등 많은 정보들이 나타나지 않고 있습니다.
원인 파악
이유는 바로 Slack 로깅을 위한 위에 있는 여러 Context 정보등을 MDC 를 활용해서 저장하고 호출하고 있는데 MDC 는 기본적으로 ThreadLocal 를 만들어서 정보를 저장한다는 점입니다. (MDC 에 대한 타 블로그 정보)
public class LogbackMDCAdapter implements MDCAdapter {
final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal();
private static final int WRITE_OPERATION = 1;
private static final int MAP_COPY_OPERATION = 2;
final ThreadLocal<Integer> lastOperation = new ThreadLocal();
// 중략
아시다시피 스프링에서 Web Request 가 오게 되면 하나의 쓰레드를 할당해서 해당 작업을 처리하게 되는데, 이때 Thread 에 대한 정보를 ThreadLocal 에 저장하게 되면 해당 작업이 끝날 때 까지 모든 상황에서 context 를 유지하고 저장하고 찾아볼 수 있어서 편합니다. MDCAdapter 가 이런 방식을 활용해서 구현이 되어있기에 저희는 MDC 를 사용하고 있었습니다.
하지만, 비동기 처리를 위해 TaskExecutor 를 활용하기 시작하면 해당 executor 는 새로운 Thread 를 생성하게 되는데 이 쓰레드에는 기존 쓰레드의 context 가 넘어가지 않고 새로 만들어지기 때문에 저렇게 다 빈값으로 나오게 됩니다.
다시 말해 비동기 처리시 logging 정보를 지금처럼 ThreadLocal 사용하게 되면
스레드에 저장된 정보가 새로운 비동기 쓰레드에 전달 안됨 → 스레드 context 활용하는 MDCUtil 을 이용해 처리하는 모든 로깅이나 로직이 먹통이 되는 거죠
해결방법
InheritableThreadLocal 사용
여기저기 검색해보니 그냥 새로운 스레드가 아니라 상속이 가능한 스레드인 IngeritableThreadLocal 을 사용 가능하긴 한데 여기저기 side-effect 에 대한 경고가 많았습니다.
→ 티몬 블로그 보니까 엄청 복잡한 문제들을 해결... 집념과 실력이 대단해 보였지만 그렇게까지 할 엄두와 시간이 안나서 재검색을 시작..;;
TaskDecorator 활용
Spring 4.3 이상부터 제공되는 TaskDecorator 를 이용해서 비동기처리하는 taskExecutor 생성시 커스터마이징이 가능하다는 것을 찾게 되었습니다.
기존 스레드의 MDC 전체값을 카피해서 넣어 버리는 형태인데 당연히 기존 스레드와 분리 되어 있어서 값만 일치 할뿐 서로 연결되지 않으니 side effect 도 없어보였습니다. (새로 생겨난 async 스레드가 기존스레드의 context 를 바꿀 일 도 없기떄문에)
configuration 과 decorator
public class ClonedTaskDecorator implements TaskDecorator {
@Override
public Runnable decorate(Runnable task) {
Map<String, String> callerThreadContext = MDC.getCopyOfContextMap();
return () -> {
MDC.setContextMap(callerThreadContext);
task.run();
};
}
}
먼저 TaskDecorator 를 상속받아 커스텀한 데코레이터를 만든 뒤, 위 코드처럼 생성시 콘텍스트를 모두 복제해주게 합니다.
그리고 아래처럼 설정하면서 setTaskDecorator 를 이용해 위에 생성된 것을 세팅합니다.
@Configuration
@EnableAsync
public class AsyncConfig {
@Bean
public TaskExecutor taskExecutor() {
ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
// 아시겠지만.. corePool 이 기본 스레드 풀 개수
// maxPool 이 최대 개수
// queueCapacity 가 맥스이상의 업무가 몰려오면 큐 개수만큼은 저장해둘 수 있다는 뜻. 단, 그 이상이 들어오면 탈락시켜버린다.
taskExecutor.setCorePoolSize(20);
taskExecutor.setMaxPoolSize(50);
taskExecutor.setQueueCapacity(200);
taskExecutor.setMaxPoolSize(50);
// 내가 만든 데코레이터 설정
taskExecutor.setTaskDecorator(new ClonedTaskDecorator());
taskExecutor.setThreadNamePrefix("async-task-");
taskExecutor.setThreadGroupName("async-group");
return taskExecutor;
}
}
이 설정이면 끝이다. 너무나 간단하다!
이렇게 만들어서 async 메소드에서 MDC 을 통해 기존 스레드에서 설정한 값을 호출해보면 이전과 다르게 null 이 아니라 값이 들어있음을 볼 수 있습니다. (MDC 가 무엇이고 왜 쓰는지는 아래 블로그나 구글링 참고~)
로그시스템 #4-MDC를 이용하여 쓰레드별로 로그 분류하기
검색하다가 보면 상속스레드에서 생길 수 있는 문제가 있다고 해서 좀 더 테스트를 해보았습니다.
스레드풀에서 가져다가 만들다보니, 새로운 비동기 처리를 할때 지정한 스레드가 상속받아서 만든 스레드가 아니라 스레드풀에 있던 다른 스레드가 배정될 때가 있다는 제보.( 일단 이건 inheritableThreadLocal 에서의 이슈였지만)
혹시 몰라 120개 정도 태스크를 동시 생성해 봤을때도 전혀 꼬이지 않음을 확인했습니다.
테스트 코드
// TestController.class
@RequestMapping(value = "/async", method = RequestMethod.GET)
public String asyncTest() throws InterruptedException, ExecutionException, TimeoutException {
for(int i = 0; i < 120; i++) {
logger.info("============="+i);
MDCUtil.set("a", i+"");
logger.info(MDCUtil.get("a"));
testService.asyncTest(i);
logger.info("============="+i);
}
return "end";
}
// TestService.class
@Async
public void asyncTest(int val) {
logger.info(MDCUtil.get("a")+":"+val);
}
테스트 결과
(메소드가 직접 던진 숫자와 스레드에 저장된 숫자 모두 일치)
2019-08-25 04:18:34.910 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [270] : =============69
2019-08-25 04:18:34.910 INFO --- [ async-task-20] com.example.service.TestService [112] : 60:60
2019-08-25 04:18:34.911 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [272] : 69
2019-08-25 04:18:34.911 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [274] : =============69
2019-08-25 04:18:34.912 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [270] : =============70
2019-08-25 04:18:34.913 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [272] : 70
2019-08-25 04:18:34.915 INFO --- [ async-task-12] com.example.service.TestService [112] : 66:66
2019-08-25 04:18:34.915 INFO --- [ async-task-19] com.example.service.TestService [112] : 62:62
2019-08-25 04:18:34.915 INFO --- [ async-task-10] com.example.service.TestService [112] : 65:65
2019-08-25 04:18:34.915 INFO --- [ async-task-3] com.example.service.TestService [112] : 64:64
2019-08-25 04:18:34.915 INFO --- [ async-task-17] com.example.service.TestService [112] : 61:61
2019-08-25 04:18:34.915 INFO --- [ async-task-9] com.example.service.TestService [112] : 63:63
2019-08-25 04:18:34.915 INFO --- [ async-task-1] com.example.service.TestService [112] : 67:67
2019-08-25 04:18:34.916 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [274] : =============70
2019-08-25 04:18:34.917 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [270] : =============71
2019-08-25 04:18:34.917 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [272] : 71
2019-08-25 04:18:34.918 INFO --- [-nio-8080-exec-3] c.h.example.controller.TestController [274] : =============71
결론
로깅을 한다거나, context 정보를 통해서 로직을 분기처리 한다거나 하는 경우가 많은데 비동기만 들어오면 다 빵꾸나 나서 골치 아픈 경우를 해결 할 수 있다니.. 너무나 마음이 편해지는 결과였습니다.
아래 그림과 같이 이전까지는 async 처리시 오류가 나도 요청URL, 사용자정보 등등의 정보가 안보였었는데 이젠 기존 스레드의 정보를 잘 보여줍니다.
하다 보니 처음 Spring 을 시작할때, 대체 리퀘스트 정보는 어디에 담아서 여기저기서 빼서 써야하는 것인지.. 매번 파라미터로 넘겨줘야 하는건가, static 은 모든 리퀘스트 공통인데? 하면서 멘붕에 빠졌던 초보 시절의 기억이 어렴풋이 나기도 했습니다.
아무튼 결론은 검색이 힘이다!! 구글만세!
잠깐! 추가된 사항 2019.08.30
MDC 없는 케이스 처리
적용 후 잘 쓰고 있었는데,, 두둥!
저희가 쓰는 Batch 처리에도 같은 로직을 적용했더니 오류가 나옵니다!!! 으악!!. NPE!!
원인을 추적해보니 배치는 TaskScheduler 라는 스레드를 통해서 스케줄링에 의한 작업을 수행하고 있었는데, 우리는 본래 Interceptor 단에서만 request 와 여러 정보를 MDC 에 저장하고 있었기에 배치 작업시에는 MDC 에 아무정보가 저장되지 않아서 null 값만 들어 있는 상태였습니다.
public class ClonedTaskDecorator implements TaskDecorator {
@Override
public Runnable decorate(Runnable task) {
Map<String, String> callerThreadContext = MDC.getCopyOfContextMap();
return () -> {
// 아래 값이 null 인 케이스도 있을테니 null 처리
if(callerThreadContext != null){
MDC.setContextMap(callerThreadContext);
}
task.run();
};
}
}
위에 처럼 null 케이스를 처리하게 바꿔났습니다.
그리고 오히려 배치일때도 로깅하기 위해서 Aspect 를 이용해서 배치 태스크 수행 전에 MDC스레드 정보 에 배치 메소드명이나 기타 정보를 저장해두고 배치에서 또 다시 @Async 등을 이용해 비동기 태스크를 불러도 해당 배치의 정보를 전달 할 수 있게 해두었습니다. Aspect 와 AOP 는 이 장의 주제가 아니니, 기회가 되면 다음에 관련 포스팅으로~!!
암튼 이제 모두 해결! 언젠가는 MDC 가 아닌 우리만의 구조체를 가지고 위의 문제를 처리하는 방식을 고민해보고자 합니다.