Log4j2 Async logger 와 shutdown hook 을 동시 사용할 경우 주의할 점
Log4j2 에서는 low-latency 로 로그를 남길 수 있도록 Asynchronous logger 를 지원하고 있다. Storm 프로젝트에서도 0.10 버전부터 Logback 에서 Log4j2 로 건너오면서 Async logger 를 설정하여 사용하고 있다.
최근 1.1.0 릴리즈 준비로 남은 이슈들을 해결하면서 한 이슈에서 worker 의 shutdown 시작 이후의 로그가 불안정하게 기록된다는 것을 발견했다. 정확하게는 높은 확률로 어느 시점 이후의 로그가 기록되지 않았다. 초기에는 worker 가 해당 시점에 종료되는 것으로 생각했는데 좀 더 파고들어보니 로그만 기록되지 않는 것으로 파악되었다.
원인은 나름 심오했는데, JVM 의 shutdown hook 동작과 Log4j2 Async logger 의 리소스 정리가 맞물려서 발생한 증상으로 파악되었다.
먼저 JVM shutdown hook 의 특성을 살펴보면…
- 여러 shutdown hook 들을 등록할 수 있다.
- JVM 은 shutdown hook 들의 실행 순서를 보증하지 않는다.
- shutdown hook 들은 concurrent 하게 실행된다.
- (관련성은 적지만) shutdown hook 에서 System.exit() 를 호출하면 deadlock 이 된다. 강제 종료하고 싶으면 Runtime.getRuntime().halt() 를 실행해야 한다.
Storm 의 경우 worker 프로세스의 정리를 shutdown hook 으로 걸어 두고, supervisor 에서 worker 를 종료할 때 SIGTERM 을 날려 worker 프로세스의 shutdown hook 이 실행되도록 하고, 몇 초 대기 후 프로세스가 종료되지 않았으면 SIGKILL 로 강제 종료한다. 프로세스 정리 중에도 정리 상태를 남기기 위해 로그를 기록하고 있다.
문제는, Log4j2 또한 리소스 정리를 shutdown hook 에 걸어 두고, 리소스 정리하는 과정이 완료되면 로그를 처리하지 않게 된다는 것이다. JVM shutdown hook 의 특성 2, 3 에 따르면 Log4j2 의 리소스 정리 hook 은 다른 shutdown hook 들보다 먼저 끝날 수 있고, 그 이후부터 다른 shutdown hook 들의 로그 기록은 실패하게 된다.
Storm 에서 사용하는 Log4j2 버전이 낮아 (2.1, 사이트에서는 2.3 도 legacy 메뉴에 있다.) 다른 좋은 방안은 찾지 못했고, 가장 쉬운 방안인 shutdown hook 을 disable 하는 것으로 우선 패치를 제출해 두었다.
(방법은 간단하다. configuration 태그에 shutdownHook=”disable” 을 추가하면 된다.)
리소스 정리 hook 을 끄는 거라 조금 찜찜해서 Log4j2 상위 버전에서 더 깔끔한 종료 방안이 있으면 버전도 올리면서 방법도 바꿀 계획이다.
