コピペで始めるSLF4J & Logback

#Java

まこたん

2013.07.11

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

SLF4J & Logback

JavaのLoggerといえばlog4jで十分なのでlog4jを使ってる場合も多いと思います。
ログの出力性能は最終的にはディスクの速度で決まり、ログ出力の要件は案件が変わってもそれほど変化することもないのでlog4jの定義ファイルもコピペして再利用すればいいですし、新たなLoggerを使うのは手間でしかありません。
今回紹介するSLF4J & Logbackは既存のソースコードに手を入れること無く、しかも他のLoggingライブラリのログ出力も統合できます。

SLF4J

SLF4Jはロギング実装を持たず、出力先毎のライブラリを入れ替えることで色々なLoggingライブラリに対応しているFacadeです。
SLF4Jには標準でplaceholderを使えるAPIもあるのでlog4jなどでよく書いてたlog出力前に不要な文字列結合を避けるためのif文は必要なくなります。

        // log4jなどでよくある不要な文字列結合を避ける為の記述
        if (logger.isDebugEnabled()) {
            logger.debug("debug message " + i);
        }
        
        // SLF4Jで上記と同じ意味の実装
        logger.debug("debug message {}", i);

さらに、他のLoggingライブラリのAPIを模倣したjarを追加することで他のLoggingライブラリを使っている場合でも、簡単にSLF4Jへ乗り換えることが可能です。

Logback

SLF4Jと組み合わせて使うことの多いと思われるLogging実装です。 logback.xmlを定義することでLogging設定を変更できます。特徴的な機能としてはpropertyファイルからの値の取得やgroovyファイルを設定ファイルとして利用することが可能です。
ユーザや環境固有の設定をpropertyファイルに外出しすることでLoggingの設定を開発者毎にログレベルを変更したりが自由にできるようになります。
Logbackを利用しようとおもったきっかけになったのは、logのローテート設定でzipなどへ圧縮して別のディレクトリに移す機能です。これの機能を使えば開発中にdebugログがディスクを圧迫することもなく便利です。
さらに、移動先をs3fs等でマウントしておけばそのままS3へアップロードすることも可能になります。

設定

mavenをご利用の方はdependenciesに以下を追加します。
maven以外の依存性解決ツールをご利用の方は以下を見ながら追加してください。

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>[1.0,)</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-simple</artifactId>
    <version>[1.7,)</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>[1.7,)</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>[1.7,)</version>
</dependency>

依存性解決ツールを使ってない場合は slf4jのダウンロードページとlogbackのダウンロードページから必要なファイルをダウンロードして依存jarに追加して下さい

コピペ用 logback.xml

この中身をlogback.xmlとしてclasspath上になるように保存してください。
コピペしにくい場合はこのリンクから同じ物を取得可能です

<configuration>

    <property name="LoggingDir" value="logs/" />
    <property name="ROOT_LEVEL" value="TRACE" />
    <timestamp key="byDate" datePattern="yyyyMMdd"/>


    <appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>TRACE</level>
        </filter>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{yyyy-MMM-dd HH:mm:ss.SSS} %-5level %marker %logger - %msg%n</Pattern>
        </layout>
    </appender>

    <appender name="DEBUG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <append>true</append>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>TRACE</level>
        </filter>
        <file>${LoggingDir}debug.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LoggingDir}history/debug.%d{yyyy-MM-dd}.zip</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>time:%d{yyyy-MMM-dd HH:mm:ss.SSS} level:%level %marker thread:%thread logger:%logger message:%msg%n
            </pattern>
        </encoder>
    </appender>

    <appender name="INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <append>true</append>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <file>${LoggingDir}info.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LoggingDir}history/info.%d{yyyy-MM-dd}.zip</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>time:%d{yyyy-MMM-dd HH:mm:ss.SSS}	level:%level	%marker	thread:%thread	logger:%logger	message:%msg%n
            </pattern>
        </encoder>
    </appender>

    <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <append>true</append>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
        <file>${LoggingDir}error.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LoggingDir}history/error_%d{yyyy-MM-dd}.zip</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>time:%d{yyyy-MMM-dd HH:mm:ss.SSS}	level:%level	%marker	thread:%thread	logger:%logger	message:%msg%n
            </pattern>
        </encoder>
    </appender>

    <appender name="ASYNC_STDOUT1" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="STDOUT1"/>
    </appender>

    <appender name="ASYNC_INFO" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="INFO"/>
    </appender>

    <appender name="ASYNC_ERROR" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="ERROR"/>
    </appender>

    <appender name="ASYNC_DEBUG" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="DEBUG"/>
    </appender>


    <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
        <Marker>org.domain.library</Marker>
        <OnMatch>ACCEPT</OnMatch>
    </turboFilter>
    <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
        <Marker>org.apache.http</Marker>
        <OnMatch>DENY</OnMatch>
    </turboFilter>
    <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
        <MDCKey>username</MDCKey>
        <Value>sebastien</Value>
        <OnMatch>ACCEPT</OnMatch>
    </turboFilter>


    <!-- This file appender is used to output aggregated performance statistics -->
    <appender name="perf4jFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${LoggingDir}perf4j.log</File>
        <encoder>
            <Pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n</Pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LoggingDir}perf4j.%d{yyyy-MM-dd}.log</FileNamePattern>
        </rollingPolicy>
    </appender>

    <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="perf4jFileAppender"/>
    </logger>

    <logger name="org.springframework" level="INFO">
        <appender-ref ref="ASYNC_STDOUT1"/>
        <appender-ref ref="ASYNC_INFO"/>
    </logger>

    <logger name="com.amazonaws" level="INFO">
        <appender-ref ref="ASYNC_STDOUT1"/>
        <appender-ref ref="ASYNC_INFO"/>
    </logger>

    <logger name="org.apache.http" level="INFO">
        <appender-ref ref="ASYNC_STDOUT1"/>
        <appender-ref ref="ASYNC_INFO"/>
    </logger>

    <logger name="org.apache.commons.configuration" level="INFO">
        <appender-ref ref="ASYNC_STDOUT1"/>
        <appender-ref ref="ASYNC_INFO"/>
    </logger>

    <logger name="freemarker" level="INFO">
        <appender-ref ref="ASYNC_STDOUT1"/>
        <appender-ref ref="ASYNC_INFO"/>
    </logger>




    <root level="${ROOT_LEVEL}">
        <appender-ref ref="STDOUT1"/>
        <appender-ref ref="INFO"/>
        <appender-ref ref="ERROR"/>
        <appender-ref ref="ASYNC_DEBUG"/>
    </root>
</configuration>

logback.xmlの説明

設定	行数(開始位置)	設定内容	コメント
ログ出力先	3行目	javaの実行ディレクトリ直下の logs/	絶対パスで定義するとそこに出力可能です。環境変数も使えます
ログレベル	4行目	TRACE	よく設定するのは TRACE DEBUG INFO WARN の４つです
コンソール出力	８行目	TRACE以上のすべてのログが出力対象です。パターンは短めに設定してます
DEBUG出力	17行名	TRACE以上のすべてのログが出力対象です。パターンは詳細に出力するようにしてます	前日分のログはzipに圧縮してログ出力先のhistoryディレクトリへ自動的に30個分バックアップします
INFO出力	33行目	INFOレベルのログのみ出力対象です。パターンは詳細に出力するようにしてます	前日分のログはzipに圧縮してログ出力先のhistoryディレクトリへ自動的に30個分バックアップします
ERROR出力	51行目	WARN以上のすべてのログが出力対象です。パターンは詳細に出力するようにしてます	前日分のログはzipに圧縮してログ出力先のhistoryディレクトリへ自動的に30個分バックアップします
非同期INFO出力	67行目		INFOのAppenderに対して出力を非同期化します。大量のログ出力が発生する場合に利用します
非同期ERROR出力	71行目		ERRORのAppenderに対して出力を非同期化します。大量のログ出力が発生する場合に利用します
非同期DEBUG出力	75行目		ERRORのAppenderに対して出力を非同期化します。大量のログ出力が発生する場合に利用します
MarkerFilter	92行目		Markerを利用したFilterです
プロダクト毎のログ出力制御	107行目		ログ出力が多いいくつかのComponentのログをINFOに設定しています
rootレベル定義	139行目	STDOUT1,INFO,ERROR,ASYNC_DEBUGへ出力	大量のログが出る場合はそれぞれASYNCに変えるとログ出力がきっかけの遅延を抑えられます

まとめ

SLF4J&Logbackは既存資産が色々あるようなシステム開発の世界でも十分使えるので、ずっと使っていたLogback設定の元ファイルをテンプレートとして公開してみました。
propertyファイルの読み込みとか、logファイルの圧縮機能とかあるとちょっと嬉しい機能の他に、logback-test.xmlを置くと優先的に使われるなどたくさんの機能があるので、テンプレートに不満が出てきたらぜひ本家のリファレンスで調べてみてください。