로컬에 톰캣으로 개발 환경을 셋팅하고 스프링과 log4j를 사용하기 위해 기본적인 설정을 한 후
로깅을 해보았습니다.
log4j.xml은 /WEB-INF/classes에 있었고 기본적인 클래스패쓰에 들어가 있어서인지
web.xml에 별다른 설정을 해주지 않아도 log4j를 사용해 logging이 가능했습니다.
그런데 문제는 같은 로그가 두번씩 찍힌다는 것이었습니다..
log4j.xml의 설정은 아래와 같았습니다.
<logger name="com.tistiory.devyongsik.indexing">
<level value="debug" />
<appender-ref ref="CONSOLE" />
</logger>
<root>
<level value="warn"/>
<appender-ref ref="CONSOLE"/>
</root>
<level value="warn"/>
<appender-ref ref="CONSOLE"/>
</root>
문제는.. com.tistiory.devyongsik.indexing 이 패키지안에서 로깅을 하는 것들이
2번씩 중복되어서 나타나는 것이었습니다.
root 로거에 대한 설정을 지우면 한번만 찍히지만
그렇게 되면 tomcat이 구동될때, log4j의 설정을 찾지 못 한다고 나옵니다.
log4j:WARN No appenders could be found for logger (org.apache.catalina.startup.TldConfig).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN Please initialize the log4j system properly.
톰캣이 구동될때는 common-logging.jar와 tomcat/conf/logging.properties를 이용해서 로깅이 되고
그 후에 spring이나 이쪽에서 해당 webapplication에 설정되어 있는 log4j.xml을 이용해서 로깅하려고 할 때
org.apache.catalina.startup.TldConfig 이 패키지에 대해서 로거가 설정되어있는 부분이 없어서 저런 warning 메시지가 나오는 것 같습니다.
(Root 로거 설정이 있을 때 WARN 메시지가 나오지 않는 이유는 당연히 Root 로거가 최상위 로거이기 때문입니다.)
실제로 처음 톰캣이 구동될때의 로깅 메시지는
2008. 12. 17 오후 4:31:30 org.apache.coyote.http11.Http11BaseProtocol init
정보: Initializing Coyote HTTP/1.1 on http-8889
2008. 12. 17 오후 4:31:30 org.apache.catalina.startup.Catalina load
정보: Initialization processed in 468 ms
이렇게 tomcat/conf/loggin.properties 에 설정되어있는 레이아웃이고
제가 WEB-INF/classes/log4j.xml에
<logger name="org.apache.catalina.startup">
<level value = "debug" />
<appender-ref ref="CONSOLE" />
</logger>
이렇게 로거에 대한 설정을 추가하였을때는 위에서 나오던 warning 메시지는 나오지 않고<level value = "debug" />
<appender-ref ref="CONSOLE" />
</logger>
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePaths(576) || Accumulating TLD resource paths
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePaths(583) || Scanning <taglib> elements in web.xml
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp/analyzerTest.jsp subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp/searchResult.jsp subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePaths(583) || Scanning <taglib> elements in web.xml
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp/analyzerTest.jsp subdirectory
12.17 04:31:30 오후 DEBUG - TldConfig.tldScanResourcePathsWebInf(629) || Scanning TLDs in /WEB-INF/jsp/searchResult.jsp subdirectory
이렇게 로깅이 됩니다. 그리고 이때의 로깅 레이아웃 패턴은 tomcat/conf/logging.properties에 설정되어 있는 패턴이 아니라, 제가 WEB-INF/classes/log4j.xml에 설정해 놓은 레이아웃 패턴으로 나오게 됩니다. 그리고 다시
2008. 12. 17 오후 4:31:32 org.apache.coyote.http11.Http11BaseProtocol start
정보: Starting Coyote HTTP/1.1 on http-8889
2008. 12. 17 오후 4:31:32 org.apache.catalina.startup.Catalina start
정보: Server startup in 2391 ms
2008. 12. 17 오후 4:32:12 org.apache.catalina.core.StandardContext reload
정보: Reloading this Context has started
정보: Starting Coyote HTTP/1.1 on http-8889
2008. 12. 17 오후 4:31:32 org.apache.catalina.startup.Catalina start
정보: Server startup in 2391 ms
2008. 12. 17 오후 4:32:12 org.apache.catalina.core.StandardContext reload
정보: Reloading this Context has started
이런식으로 tomcat/conf/logging.properties에 설정되어있는 패턴으로 로깅이 되게 됩니다.
하나의 webapplication을 구동 할 때 퍼올려지는 순서에 상관이 있는건지도 모르겠습니다.
자세한 내용을 아신다면 코멘트를 부탁드리겠습니다.^^
아무튼 전부다 구동이 되고 이후 로깅을 할 때 위 패키지에서 (com.tistiory.devyongsik.indexing)에서 로깅을 할 때 로깅이 두번씩 된다는 것이 문제였습니다.
root 설정을 지우면 위에서 방금 말씀드린대로 톰캣 구동시 warning 메시지를 보게 되구요..
무슨 방법이 없을까 하고 찾아보다가 .. 이런 내용을 발견했습니다.
"logger는 기본적으로 정의한 패키지의 상위로부터 모든 appender를 상속받는다."
그렇다면 root 로거에서 설정한 appender를
<logger name="com.tistiory.devyongsik.indexing">
<level value="debug" />
<appender-ref ref="CONSOLE" />
</logger>
이 로거에서도 상속받게 되고 그래서 두번 찍히는 것이 아닌가 하는 생각이 들었습니다.<level value="debug" />
<appender-ref ref="CONSOLE" />
</logger>
(물론 설정 때문에 두번찍힌다는 것은 알고 있었습니다. root 로거에 대한 설정을 지우면 한번만 찍히니까요 ^^)
상속받은걸로도 찍고, 자기걸로도 찍고... 말이죠
이것은 하나의 로거에서 여러 다른 appender로 동시에 로그를 출력 할 수 있는 장점이 있습니다. 아마 그래서 그런
구조를 선택한게 아닌가 싶기도 하구요.. 하지만 그렇다고 해서 같은 로그가 두번씩 찍히는 것은 좀 아니잖아요?
ㅎㅎ
이것을 해결하기 위해 로거를 설정 할 때의 옵션이 있습니다.
바로 additivity라는 것입니다. 이것을 logger의 attribute로 지정해주면 됩니다.
<logger name="com.tistiory.devyongsik.indexing" additivity="false">
<level value="debug" />
<appender-ref ref="CONSOLE" />
</logger>
<level value="debug" />
<appender-ref ref="CONSOLE" />
</logger>
이렇게되면 이 로거는 상위로부터 내려오는 appender를 상속을 하지 않게 됩니다.
(내부적으로 상속자체를 안 받는건지 받은 걸 안 쓰는건지는 잘 모르겠습니다 -_-)
그리고 또 하나의 방법이 있습니다.
root 로거가 console로 찍히고 위 com.tistory.devyongsik.indexing 로거도 console로 찍혀야 하는데 appender가 상위로부터 상속받아지는 것이라면 굳이 같은 appender를 통해서 로깅이 되는 것들은 appender를 지정하지 않아도 될 것입니다.
즉, 아래와 같이 설정을 해줘도 됩니다.
<logger name="com.tistiory.devyongsik.indexing" >
<level value="debug" />
</logger>
<level value="debug" />
</logger>
이렇게 설정하면 상속받은 appender 만으로 로깅을 하게 됩니다.
만약 ,
<logger name="com.tistiory.devyongsik.indexing" >
<level value="debug" />
<appender-ref ref="다른APPENDER" />
</logger>
<level value="debug" />
<appender-ref ref="다른APPENDER" />
</logger>
라고 설정하면, 이 로거는 root로부터 받은 CONSOLE Appender와
자기가 가지고 있는 다른APPENDER를 통해 동시에 로깅을 하게 됩니다.