Logging libraries : log4j 2부

1.3. log4j.xml
 - 또 하나의 설정 파일인 log4j.xml에 대해 알아보자. 단순히 log4j.properties 파일을 XML 형식으로 만든것이라고 보면된다.
   (클래스패스에 log4j.xml, log4j.properties 두 파일이 동시에 존재하면 log4j.xml가 우선시 된다.)

### log messages to stdout ###
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n
 
### messages to file mylog.log ###
log4j.appender.file=org.apache.log4j.FileAppender
log4j.appender.file.File=c:/mylog.log
log4j.appender.file.Append=true
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n
 
log4j.rootLogger=trace, stdout, file

이라면,

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
    	<param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n"/>
        </layout>
    </appender>

    <appender name="file" class="org.apache.log4j.FileAppender">
    	<param name="File" value="c:/mylog.log" />
    	<param name="Append" value="true" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n"/>
        </layout>
    </appender>
    
    <!-- Root -->
    <root>
        <level value="DEBUG"/>
        <appender-ref ref="stdout"/>
        <appender-ref ref="file"/>
    </root>
</log4j:configuration>

와 같은 정도가 된다. log4j.dtd 파일은 jar(org.apache.log4j.xml/log4j.dtd)안에 포함되어 있다.
예전에는(JDK 1.3이 대세를 이루던 시대) XML API 문제로 xml 설정파일을 제대로 파싱(parsing)하지 못하는 문제가 있었지만, 지금은 별 부담없이 사용할수 있다.
참고로 말하자면 log4j는 xml 파일을 분석하기 위한 DOM Parser 선택을 jaxp를 이용해서 한다. jaxp는 클래스패스 안에 있는 라이브러리(jar)들중 먼저 발견되는 XML API 구현체를 사용해버리기 때문에 이상한(?) 라이브러리가 선택됬을 경우 에러가 발생하는 것이다.
이것을 방지하자면 자바 실행시에 "javax.xml.parsers.DocumentBuilderFactory=사용할DocumentBuilderFactory" 를 지정해주면 된다.

java -Djavax.xml.parsers.DocumentBuilderFactory=org.apache.crimson.jaxp.DocumentBuilderFactoryImpl 실행클래스

JDK 1.4이후에는 jaxp나 crimson이 표준API로 편입되어서 걱정을 안해도 된다.
앞으로는 log4j.xml 파일을 가지고 설명을 하겠다. xml 설정파일이 properties 파일에 비해 직관적이고, 지원하는 기능(Filter, Appender 안에 Appender 넣기)이 조금 더 많기 때문이다.

 - log4j는 카테고리 기능을 제공한다고 했다. 그렇다면 카테고리별로 출력을 다르게 해보자. 아래처럼 xml을 수정하면 된다.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
    	<param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n"/>
        </layout>
    </appender>

    <appender name="file" class="org.apache.log4j.FileAppender">
    	<param name="File" value="c:/mylog.log" />
    	<param name="Append" value="true" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n"/>
        </layout>
    </appender>

    <logger name="test.log4j">
        <level value="INFO" />
        <appender-ref ref="file" />
    </logger>
        
    <!-- Root -->
    <root>
        <level value="DEBUG" />
        <appender-ref ref="stdout" />
    </root>
    
</log4j:configuration>

 - logger 태그(tag)를 사용해서 카테고리별로 level 및 appender를 지정할 수 있다. 일반적(?)으로는 logger 태그 대신 category 태그를 많이 사용하고, level 태그 대신 priority 태그를 많이 사용하고 있다.
  log4j 1.2까지는 문제가 없으나 1.3부터는 category가 logger 태그로 흡수되고, priority 태그가 deprecated 취급을 당하니 가능하면 logger, level 태그를 사용하게 정신건강에 좋다.
 - 위에처럼 설정했다면 "test.log4j" 카테고리에서 발생하는 INFO 레벨 이상의 로그는 파일로 출력된다.
 - 만약 카테고리가 중복되는곳에 동일한 appender를 사용하면 어떻게 될까? 한번 설정 파일을 바꾼후 실행보자.

    <logger name="test.log4j">
        <level value="INFO" />
        <appender-ref ref="stdout" />
    </logger>
        
    <!-- Root -->
    <root>
        <level value="DEBUG" />
        <appender-ref ref="stdout" />
    </root>

* 실행결과
[18:07:48.203] FATAL TestLog4j.main(TestLog4j.java:9) - FATAL 메시지 입니다
[18:07:48.203] FATAL TestLog4j.main(TestLog4j.java:9) - FATAL 메시지 입니다
[18:07:48.203] ERROR TestLog4j.main(TestLog4j.java:10) - ERROR 메시지 입니다
[18:07:48.203] ERROR TestLog4j.main(TestLog4j.java:10) - ERROR 메시지 입니다
[18:07:48.203] WARN  TestLog4j.main(TestLog4j.java:11) - WARN 메시지 입니다
[18:07:48.203] WARN  TestLog4j.main(TestLog4j.java:11) - WARN 메시지 입니다
[18:07:48.203] INFO  TestLog4j.main(TestLog4j.java:12) - INFO 메시지 입니다
[18:07:48.203] INFO  TestLog4j.main(TestLog4j.java:12) - INFO 메시지 입니다


 - 결과는 불행히도 동일한 로그가 두번씩 출력 된다. 이럴경우 looger 태그에 additivity="false" 옵션을 주면 중복출력되는것을 막을 수 있다.(additivity의 기본값은 true이다.)
 - 그리고 여기서 한가지 더 주의깊게 봐야할 부분이 있는데, INFO 레벨까지 로그가 출력되는것이다. root 카테고리에 DEBUG 레벨을 설정했으니, DEBUG 메시지도 출력되는게 맞는것이 아닌가하고 착각을 할 수 있는데, 설정한 카테고리(test.log4j)의 로그 레벨이 INFO이므로, INFO 메시지까지만 출력이 된다. 즉, 해당 카테고리의 로그 레벨이 설정되어 있으면 그 로그 레벨을 따라간다는것이다.

    <logger name="test.log4j" additivity="false">
        <level value="INFO" />
        <appender-ref ref="stdout" />
    </logger>
        
    <!-- Root -->
    <root>
        <level value="DEBUG" />
        <appender-ref ref="stdout" />
    </root>

* 실행결과
[18:08:52.875] FATAL TestLog4j.main(TestLog4j.java:9) - FATAL 메시지 입니다
[18:08:52.875] ERROR TestLog4j.main(TestLog4j.java:10) - ERROR 메시지 입니다
[18:08:52.875] WARN  TestLog4j.main(TestLog4j.java:11) - WARN 메시지 입니다
[18:08:52.875] INFO  TestLog4j.main(TestLog4j.java:12) - INFO 메시지 입니다

- 정상적(?)으로 출력이 된다.

1.4. Appender
 log4j의 Appender들은 org.apache.log4j.Appender 인터페이스를 구현하게 되어있는데, 실제적으로 org.apache.log4j.AppenderSkeleton 추상 클래스를 상속받고 있다.

org.apache.log4j.Appender
  +- org.apache.log4j.AppenderSkeleton
       +- org.apache.log4j.AsyncAppender
       +- org.apache.log4j.jdbc.JDBCAppender
       +- org.apache.log4j.net.JMSAppender
       +- org.apache.log4j.lf5.LF5Appender
       +- org.apache.log4j.nt.NTEventLogAppender
       +- org.apache.log4j.performance.NullAppender
       +- org.apache.log4j.net.SMTPAppender
       +- org.apache.log4j.net.SocketAppender
       +- org.apache.log4j.net.SocketHubAppender
       +- org.apache.log4j.net.SyslogAppender
       +- org.apache.log4j.net.TelnetAppender
       +- org.apache.log4j.WriterAppender
            +- org.apache.log4j.ConsoleAppender
            +- org.apache.log4j.FileAppender
                 +- org.apache.log4j.DailyRollingFileAppender
                 +- org.apache.log4j.RollingFileAppender
                      +- org.apache.log4j.varia.ExternallyRolledFileAppender

- AppenderSkeleton
 + Threshold  : 이 AppenderSkeleton 클래스에는 중요한 옵신이 하나 있는데, 바로 Threshold 이다. 이 Threshold은 어떠한 Appender에도 쓸 수 있는 공통 옵션이라고 보면 된다. 이 Threshold 옵션이 하는 역할은 지정한 레벨 미만의 로그 이벤트를 무시하는것이다. 즉, 아래처럼 INFO로 설정하면 INFO 이상의 레벨만 출력이 되는것이다.

    <appender name="file" class="org.apache.log4j.FileAppender">
    	<param name="Threshold" value="INFO" />
    	<param name="File" value="c:/mylog.log" />
    	<param name="Append" value="true" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss.SSS}] %-5p %C{1}.%M(%F:%L) - %m%n"/>
        </layout>
    </appender>

사실 로그 레벨에 ALL, OFF라는 놈들도 있다. OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL 이렇게 되는데, Threshold를 OFF 로 해버리면 해당 Appender에서는 아무것도 출력이 안되는것이다.

 - WriterAppender : 이것 자체를 사용하는것은 아니지만, 자주 사용하는 Appender들이 이 WriterAppender를 상속받고 있다.
   + ImmediateFlush : 즉시 flush()(버퍼의 내용을 반영하는것)를 할지 여부이다. true 또는 false 값을 사용할 수있다. 기본값을 true이다.
   + Encoding : 출력스트림(OutputStreamWriter)의 인코딩을 설정한다. 기본값은 OS의 기본 인코딩을 따른다.
   + Threshold  : AppenderSkeleton으로부터 상속

 - ConsoleAppender : 콘솔(stdout, stderr)로 출력을 해준다.
  + Target : 표준출력(System.out), 표준에러출력(System.err)인지 설정할 수 있다. 기본값은 System.out 이다.
  + ImmediateFlush : WriterAppender로부터 상속
  + Encoding : WriterAppender로부터 상속
  + Threshold  : AppenderSkeleton으로부터 상속

 - FileAppender : 이름그대로 파일에 로그룰 출력해 준다. 이놈도 이것 자체적으로는 잘 사용되지 않는다. 한 파일에 모든 로그가 출력된다고 생각해봐라. 끔찍하다. 초거대 파일을 열어볼려면.... OTL... 그래서 파일을 특정 크기로 나눠서 출력(RollingFileAppender)하거나, 특정 주기로 나눠서 출력(DailyRollingFileAppender)하는 하위 Appender를 많이 사용한다.
  + File : 출력할 파일명을 설정한다.
  + Append : 추가모드인지 설정한다. true 또는 false 값을 설정할 수 있고, 기본값을 false이다.
  + BufferedIO : 버퍼를 사용할지 여부를 설정한다.  true 또는 false 값을 설정할 수 있고, 기본값을 false이다.
  + BuffereSize : 버퍼를 사용할 경우 버퍼 사이즈이다.
  + ImmediateFlush : WriterAppender로부터 상속
  + Encoding : WriterAppender로부터 상속
  + Threshold  : AppenderSkeleton으로부터 상속

 - RollingFileAppender : 파일을 지정한 크기까지 출력해준다. 지정 크기를 넘어면 기존 파일은 mylog.log.1이라는 이름으로 백업되고 새로운 mylog.log란 파일에 로그가 출력된다.
  + MaxFileSize: 파일의 최대 크기이다. "1024", "1KB", "2MB", "3GB" 같이 지정할 수 있다. 기본값을 10MB이다.
  + MaxBackupIndex : 최대 크기가 넘어가면 백업 파일이 만들어지는데, mylog.log.1, mylog.log.2 이런씩으로 계속 증가한다. 만약 이 값이 1이라고 지정되어 있으면 mylog.log.1까지만 백업이 만들어지고 기존꺼는 삭제된다. 기본값을 1이다.
  + File : FileAppender로부터 상속
  + Append : FileAppender로부터 상속
  + BufferedIO : FileAppender로부터 상속
  + BuffereSize : FileAppender로부터 상속
  + ImmediateFlush : WriterAppender로부터 상속
  + Encoding : WriterAppender로부터 상속
  + Threshold  : AppenderSkeleton으로부터 상속

 - DailyRollingFileAppender : 파일을 지정한 주기로 나눠서 출력한다. DatePattern 옵션을 줘서 매월(MM), 매주(ww), 매일(dd), 오전/오후(a),  매시(HH), 매분(mm)을 설정한수 있다.
  + DatePattern : 기본값은 "'.'yyyy-MM-dd"이다. 즉 주기가 일단위이다.
  + File : FileAppender로부터 상속
  + Append : FileAppender로부터 상속
  + BufferedIO : FileAppender로부터 상속
  + BuffereSize : FileAppender로부터 상속
  + ImmediateFlush : WriterAppender로부터 상속
  + Encoding : WriterAppender로부터 상속
  + Threshold  : AppenderSkeleton으로부터 상속

 - 기타 여러 Appender가 있지만 생략하도록 하겠다.

1.5. 속도 향상
 - 솔직히 말하자면 속도 향상보다는 조그마한(?) 배려가 아닌가 싶다. 개발 중에는 디버그 로그를 많이 남긴다. 개발이 완료되고 실제 운영을 할 경우 그 많은 디버그 로그들을 어떻게 해야할까? 다행히도 log4j에서 로그 레벨을 지정할 수 있어서 출력이 안되게 할 수 있다. 하지만 문제는 그것뿐만이아니다. 예전에 설명했듯이 디버그 로그를 출력하기 위해 메시지를 만드는 과정에서도 연산을 한다는 것이다.
 즉, 아래와 같은 경우 "+" 연산이 일어난후 그 메시지가 log4j로 넘어간다는것이다.

 log.debug(name + "님 안녕하세요");

사실 아주 사소한(?) 자원이 소비되는것이지만, 이걸 방치하는것은 예의(?)에 어긋나는일이다. 그래서 아래처럼 해당 레벨이 출력가능한지 검사한다음 로그 출력을 한다.

 if (log.isDebugEnabled()) {
  log.debug(name + "님 안녕하세요");
 }

이렇게 함으로서 "+" 연산을 미연에 방지할 수 있는것이다. (근데 정말 빠를까...... ^^;)