slf4jとlog4j2を使たデバッグログの出力方法

2019年12月21日
2023年1月6日
Java, システムエンジニアリング

1 はじめに
2 デバッグ／トレースログを出せるようにする
3 検証プログラム
- 3.1 サンプルコード
- 3.2 実行結果

はじめに

Webアプリやスタンドアロンアプリの開発でデバッグログやトレースログを出したい場合があります。
とりあえず、ロガーのログレベルをdebugやtraceに下げればいいや、と設定してもログが出力されない場合があります。
ここでは、log4j2を例として、ログライブラリを概説し、デバッグやトレースログを出力するための方法について説明します。log4j2以外のログライブラリでも、同様の仕組みになっていることが多いので、応用できると思います。
ログ全般の設計・実装ポリシーに興味がある方には、こちらが参考になれば幸いです。
NDW
経験から思うログの設計・実装ポリシー
一般的なログ種別・ログ出力項目の紹介、例外時や稼働監視システムを考慮したログ設計の注意点等を紹介します。また、実装時のロ…

デバッグ／トレースログを出せるようにする

ログの送信元（ロガー）と送信先（アペンダ）のそれぞれにフィルタがあることを理解するのが重要です。
デバッグログやトレースログが期待通りに出力できない場合、ロガーまたはアペンダのいずれか、または両方でフィルタされている可能性があります。そのために、基本的なセオリーとして、次のように２つの設定を変更します。

ロガーのログレベルをdebugまたはtraceに変更
ロガーの設定で、デバッグまたはトレースを出力したいロガーのログレベルをdebugまたはtraceに変更します。ロガーに対して明示的にログレベルを指定しない場合、ルート(Root)のログレベルが適用されます。ルートのログレベルは基本的にinfoが設定されていることが多いので、明示的にログレベルを指定しないと、debugやtraceはアペンダに渡されません。
ルートのログレベルをdebugやtraceにする方法もありますが、これだと使用しているライブラリ等のログも出力されてしまい、大量のログが出力されてしまいます。
アペンダーの（フィルター）のログレベルをdebugまたはtraceに変更
ログを確認したいアペンダーの設定で、フィルタするログレベルをdebugまたはtraceに変更します。アペンダーは既定でログレベルinfo未満をフィルタするので、明示的にログレベルを指定されていないとdebugやtraceはフィルタされてしまいます。(ログレベル以外でフィルタすることもできるので、本来であればログレベルの変更だけでは出力されない場合があります。)

例えば、a.b.c2というロガーでdebugを出力したい場合、ロガーの設定でログレベルをdebugに変更します。また、アペンダでもログレベルをdebugに変更します。（下記はlog4j2を使用する場合のlog4j2.xmlのサンプルです。）

検証プログラム

ロガーとアペンダのログレベル指定によるログ出力を検証するためのプログラムを作成しました。
ログを出力するためのAPIとしてはslf4j、ログ出力ライブラリとしてlog4j2を使用しています。slf4jはあくまでもAPIであり、実際のログ出力はlog4j2が行うため、ロガーやアペンダのログ出力の設定はlog4j2の設定ファイル(log4j2.xml)で行います。slf4jとログライブラリの関係については、こちらがご参考になれば幸いです。

GitHub

example/log4j2-example at master · nextdoorwith/example

Contribute to nextdoorwith/example development by creating a…

サンプルコード

冒頭の説明サンプルのロガー(a.b.c1～c6)で、slf4j APIを使って、trace/debug/info/warn/errorでログを出力します。
本来であれば、慣例に従って１クラス１ロガーにすべきですが、ここではサンプルのため、１クラスで複数のロガーを使っています。

package test;import org.slf4j.Logger;import org.slf4j.LoggerFactory;public class LogTest {public static void main(String[] args) {Logger logger;logger = LoggerFactory.getLogger("a.b.c1");log(logger);logger = LoggerFactory.getLogger("a.b.c2");log(logger);logger = LoggerFactory.getLogger("a.b.c3");log(logger);logger = LoggerFactory.getLogger("a.b.c4");log(logger);logger = LoggerFactory.getLogger("a.b.c5");log(logger);logger = LoggerFactory.getLogger("a.b.c6");log(logger);}public static void log(Logger logger) {logger.trace("TRACE test");logger.debug("DEBUG test");logger.info("INFO  test");logger.warn("WARN  test");logger.error("ERROR test");}}

package test;

import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

public class LogTest {

public static void main(String[] args) {

Logger logger;

logger = LoggerFactory.getLogger("a.b.c1");

log(logger);

logger = LoggerFactory.getLogger("a.b.c2");

log(logger);

logger = LoggerFactory.getLogger("a.b.c3");

log(logger);

logger = LoggerFactory.getLogger("a.b.c4");

log(logger);

logger = LoggerFactory.getLogger("a.b.c5");

log(logger);

logger = LoggerFactory.getLogger("a.b.c6");

log(logger);

}

public static void log(Logger logger) {

logger.trace("TRACE test");

logger.debug("DEBUG test");

logger.info("INFO test");

logger.warn("WARN test");

logger.error("ERROR test");

}

ロガーとアペンダのログレベルの指定を行います。
ロガーのログレベルは冒頭の説明サンプルのように設定しています。アペンダーについては、既定(info)でフィルタするFile、debugでフィルタするFileDebug、traceでフィルタするFileTraceというアペンダを定義しています。

<?xml version="1.0" encoding="UTF-8"?><Configuration status="WARN"><Properties><Property name="base">.\log</Property></Properties><Appenders><File name="File" fileName="${base}\log.txt"><PatternLayoutpattern="▲%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" /></File><File name="FileDebug" fileName="${base}\log-debug.txt"><PatternLayoutpattern="●%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" /><ThresholdFilter level="debug" /></File><File name="FileTrace" fileName="${base}\log-trace.txt"><PatternLayoutpattern="■%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" /><ThresholdFilter level="trace" /></File></Appenders><Loggers><Logger name="a.b.c1" level="error" /><Logger name="a.b.c2" level="debug" /><Logger name="a.b.c3" level="trace" /><Root level="info"><AppenderRef ref="File" /><AppenderRef ref="FileDebug" /><AppenderRef ref="FileTrace" /></Root></Loggers></Configuration>

<?xml version="1.0" encoding="UTF-8"?>

</Properties>

<PatternLayout

pattern="▲%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />

</File>

<PatternLayout

pattern="●%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />

</File>

<PatternLayout

pattern="■%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />

</File>

</Appenders>

</Root>

</Loggers>

</Configuration>

mavenの設定は次の通りです。

<project ...<dependencies><!-- SLF4J API ======================================== --><dependency><groupId>org.slf4j</groupId><artifactId>slf4j-api</artifactId><version>1.7.25</version></dependency><!-- SLF4J binding ======================================== --><dependency><groupId>org.apache.logging.log4j</groupId><artifactId>log4j-slf4j-impl</artifactId><version>2.12.1</version></dependency></dependencies></project>

<project ...

</dependency>

<groupId>org.apache.logging.log4j</groupId>

</dependency>

</dependencies>

</project>

実行結果

eclipseから実行すると、プロジェクトフォルダトップに”log”というフォルダが作成され、このフォルダの直下に、各アペンダに対応するログファイルが作成されます。

アペンダFileの出力結果は次の通りです。
このアペンダではログレベル(<ThresholdFilter loglevel=…>)を指定していないので、info以上のログが出力されます。
ロガー側では、a.b.c1でerrorを指定しているので、このロガーではerrorのみ出力されています。それ以外のロガーinfo上が出力され、info未満のdebugやtraceは出力されません。

▲22:10:35.908 [main] ERROR a.b.c1 - ERROR test

▲22:10:35.912 [main] DEBUG a.b.c2 - DEBUG test

▲22:10:35.912 [main] INFO a.b.c2 - INFO test

▲22:10:35.913 [main] WARN a.b.c2 - WARN test

▲22:10:35.913 [main] ERROR a.b.c2 - ERROR test

▲22:10:35.913 [main] TRACE a.b.c3 - TRACE test

▲22:10:35.913 [main] DEBUG a.b.c3 - DEBUG test

▲22:10:35.914 [main] INFO a.b.c3 - INFO test

▲22:10:35.914 [main] WARN a.b.c3 - WARN test

▲22:10:35.914 [main] ERROR a.b.c3 - ERROR test

▲22:10:35.914 [main] INFO a.b.c4 - INFO test

▲22:10:35.915 [main] WARN a.b.c4 - WARN test

▲22:10:35.916 [main] ERROR a.b.c4 - ERROR test

▲22:10:35.917 [main] INFO a.b.c5 - INFO test

▲22:10:35.917 [main] WARN a.b.c5 - WARN test

▲22:10:35.917 [main] ERROR a.b.c5 - ERROR test

▲22:10:35.918 [main] INFO a.b.c6 - INFO test

▲22:10:35.918 [main] WARN a.b.c6 - WARN test

▲22:10:35.918 [main] ERROR a.b.c6 - ERROR test

アペンダFileDebugの出力結果は次の通りです。
このアペンダではログレベルとしてdebugを指定しているので、debug以上のログが出力されます。
ロガー側では、a.b.c2でdebug、a.b.c3でtraceを指定しているので、この２つのロガーでdebugが出力されています。

●22:10:35.908 [main] ERROR a.b.c1 - ERROR test

●22:10:35.912 [main] DEBUG a.b.c2 - DEBUG test

●22:10:35.912 [main] INFO a.b.c2 - INFO test

●22:10:35.913 [main] WARN a.b.c2 - WARN test

●22:10:35.913 [main] ERROR a.b.c2 - ERROR test

●22:10:35.913 [main] DEBUG a.b.c3 - DEBUG test

●22:10:35.914 [main] INFO a.b.c3 - INFO test

●22:10:35.914 [main] WARN a.b.c3 - WARN test

●22:10:35.914 [main] ERROR a.b.c3 - ERROR test

●22:10:35.914 [main] INFO a.b.c4 - INFO test

●22:10:35.915 [main] WARN a.b.c4 - WARN test

●22:10:35.916 [main] ERROR a.b.c4 - ERROR test

●22:10:35.917 [main] INFO a.b.c5 - INFO test

●22:10:35.917 [main] WARN a.b.c5 - WARN test

●22:10:35.917 [main] ERROR a.b.c5 - ERROR test

●22:10:35.918 [main] INFO a.b.c6 - INFO test

●22:10:35.918 [main] WARN a.b.c6 - WARN test

●22:10:35.918 [main] ERROR a.b.c6 - ERROR test

アペンダFileTraceの出力結果は次の通りです。
このアペンダではログレベルとしてtraceを指定しているので、trace以上のログが出力されます。
ロガー側では、a.b.c3でしかtraceを指定していないので、このロガーのみtraceが出力されています。

■22:10:35.908 [main] ERROR a.b.c1 - ERROR test

■22:10:35.912 [main] DEBUG a.b.c2 - DEBUG test

■22:10:35.912 [main] INFO a.b.c2 - INFO test

■22:10:35.913 [main] WARN a.b.c2 - WARN test

■22:10:35.913 [main] ERROR a.b.c2 - ERROR test

■22:10:35.913 [main] TRACE a.b.c3 - TRACE test

■22:10:35.913 [main] DEBUG a.b.c3 - DEBUG test

■22:10:35.914 [main] INFO a.b.c3 - INFO test

■22:10:35.914 [main] WARN a.b.c3 - WARN test

■22:10:35.914 [main] ERROR a.b.c3 - ERROR test

■22:10:35.914 [main] INFO a.b.c4 - INFO test

■22:10:35.915 [main] WARN a.b.c4 - WARN test

■22:10:35.916 [main] ERROR a.b.c4 - ERROR test

■22:10:35.917 [main] INFO a.b.c5 - INFO test

■22:10:35.917 [main] WARN a.b.c5 - WARN test

■22:10:35.917 [main] ERROR a.b.c5 - ERROR test

■22:10:35.918 [main] INFO a.b.c6 - INFO test

■22:10:35.918 [main] WARN a.b.c6 - WARN test

■22:10:35.918 [main] ERROR a.b.c6 - ERROR test