この記事は公開されてから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 の4つです |
コンソール出力 | 8行目 | 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を置くと優先的に使われるなどたくさんの機能があるので、テンプレートに不満が出てきたらぜひ本家のリファレンスで調べてみてください。