序.
서비스의 라이브러리를 대대적으로 업데이트하는등의 리팩토링 작업을 진행했다.
테스트 서버에서 아무 문제가 없는 것을 확인한 후 실서버에 배포를 했는데, 서버 20대 중 일부 서버들에서만 catalina.out에 로그가 쌓이지 않는것이다. 정확히는 tomcat이 찍는 스타팅 로그들은 쌓였지만 이후 발생하는 서비스 로그들이 하나도 쌓이지 않았다.
1. 몇차례 서버를 재기동해 보기도 하고 재배포해보기도 했다. 여전히 쌓이는 놈은 쌓이고 안쌓이는 놈은 안 쌓임.....
2. 서버별 환경차이를 확인
서버들이 한꺼번에 받았던 것이라, os버전은 물론 모든 어플리케이션 버전이 차이가 없었다. 파일 시스템의 권한도 완벽했으며, 용량 문제도 전혀 없었다.
3. 로그가 잘 쌓이는 서버와 안 쌓이는 서버의 tomcat 스타트로그를 처음부터 찬찬히 살펴보았다. 70여 라인까지는 아주 정확히 똑같이 쌓였는데, 이후로 미묘한 차이를 보였다.
잘 쌓이는 놈
...
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/web-app/WEB-INF/lib/logback-classic-1.1.8.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/web-app/WEB-INF/lib/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
Feb 02, 2017 10:30:43 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
[2017-02-02 22:30:43][localhost-startStop-1] INFO o.s.web.context.ContextLoader - Root WebApplicationContext: initialization started
...
안 쌓이는 놈
...
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/web-app/WEB-INF/lib/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/web-app/WEB-INF/lib/logback-classic-1.1.8.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
Feb 02, 2017 10:16:44 PM org.apache.catalina.core.ApplicationContext log
INFO: Initializing Spring root WebApplicationContext
log4j:WARN No appenders could be found for logger (org.springframework.web.context.ContextLoader).
...
현재 서비스의 로깅 Facade는 SLF4J 고, 실제 사용하는 로깅 프레임워크는 logback 이다. 따라서 logback 관련한 설정만 되어 있는 상태다.
SLF4J가 클래스패쓰 상에서 에서 두개의 로깅 프레임워크를 발견했고, 발견 순서가 달라지면서 잘 쌓이는 놈은 logback을 제대로 Actual binding한 반면 안 쌓이는 놈은 log4j를 Actual binding 한 것이다. log4j 관련 설정은 아예 하지 않았으므로 appender가 설정되어 있을리 없고 따라서 로그를 쓸 곳을 잃어버린 것이다.
리팩토링을 하는 과정에서 일부 라이브러리들이 Maven dependency에 추가 되었는데 이 넘들 중 slf4j-log4j12를 하위에서 사용하는 넘이 포함되어 있어서 이것이 클래스패쓰에 포함되어 버린 것이다.
SLF4J가 중복된 로거중에 하나를 선택을 하는 로직은 JVM에게 맡겨져 있으며 이는 보통 랜덤이란다;;;
(The way SLF4J picks a binding is determined by the JVM and for all practical purposes should be considered random.
from : https://www.slf4j.org/codes.html#multiple_bindings)
그래서 서버마다 다른 선택을 하게 되었고 이것이 일부서버에서만 문제가 발생한 이유다.
결국 slf4j-log4j12가 클래스패쓰에 포함되지 않게끔 dependency에 exclusion 설정을 해주어서 이 문제를 해결했다. 제거 되고 나니 SLF4J가 어떤걸 바인딩할지 고민하는 저 위의 로그 자체가 나오지 않는다.
만약 테스트서버에서 SLF4J가 잘못 선택해주었다면 일찌감치 찾아낼 수 있었을 것으로 보인다. 근데 하필 거기서는 제대로 잘 바인딩 되었다.
結.
Maven류의 빌드 도구를 많이 사용하게 되면서, 일일히 라이브러리들을 클래스패쓰에 넣는 작업을 할 필요가 없어진 편의가 있지만, 그에 따라 버전이 다른 중복된 라이브러리를 나도 모르게 쓰게 되는 경우가 많다.(이를 깔끔히 정리하는 것은 많은 수고가 필요하다.)
우리 프로젝트의 경우는 이를 꽤나 결벽스럽게 관리해왔음에도 불구하고 버전 중복이 아닌 기능 중복으로 이런 문제가 발생했다.
여하튼, Maven dependency는 완벽히 관리되어야 한다. 라이브러리 버전 중복은 예측하지 못한 컴파일/런타임 에러를 발생 시킬수 있고, 라이브러리 기능중복은 본 예와 같은 문제를 야기 시킨다. 특히나 SLF4J는 묵시적으로 로거를 선택하므로 기능 중복이 치명적인 문제를 발생 시킬 수 있다.
