アプリ開発ときどきアウトドア

主にJavaを使ったアプリ開発やトラブルシューティング等のノウハウ、キャンプや登山の紹介や体験談など。

1. システムエンジニアリング Java

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

投稿日:2019年12月21日 更新日:

Webアプリやスタンドアロンアプリの開発でデバッグログやトレースログを出したい場合があります。
とりあえず、ロガーのログレベルをdebugやtraceに下げればいいや、と設定してもログが出力されない場合があります。
ここでは、log4j2を例として、ログライブラリを概説し、デバッグやトレースログを出力するための方法について説明します。log4j2以外のログライブラリでも、同様の仕組みになっていることが多いので、応用できると思います。

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

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

  1. ロガーのログレベルをdebugまたはtraceに変更
    ロガーの設定で、デバッグまたはトレースを出力したいロガーのログレベルをdebugまたはtraceに変更します。ロガーに対して明示的にログレベルを指定しない場合、ルート(Root)のログレベルが適用されます。ルートのログレベルは基本的にinfoが設定されていることが多いので、明示的にログレベルを指定しないと、debugやtraceはアペンダに渡されません。
    ルートのログレベルをdebugやtraceにする方法もありますが、これだと使用しているライブラリ等のログも出力されてしまい、大量のログが出力されてしまいます。
  2. アペンダーの(フィルター)のログレベルを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とログライブラリの関係については、こちらがご参考になれば幸いです。

サンプルコード

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

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">
			<PatternLayout
				pattern="▲%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
		</File>
		<File name="FileDebug" fileName="${base}\log-debug.txt">
			<PatternLayout
				pattern="●%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
			<ThresholdFilter level="debug" />
		</File>
		<File name="FileTrace" fileName="${base}\log-trace.txt">
			<PatternLayout
				pattern="■%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>

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>

実行結果

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を指定しているので、この2つのロガーで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


(adsbygoogle = window.adsbygoogle || []).push({});


(adsbygoogle = window.adsbygoogle || []).push({});

-1. システムエンジニアリング, Java

執筆者:

関連記事

jQueryによるデフォルトボタンの実装

デフォルトボタンについて Webページ上でエンターキーを押した場合、そのページ上であらかじめ決められたボタンをクリックしたかのように処理を実行する仕組みがある。何らかのデータの検索を行うようなページは …

開発・検証用のFTPサーバ(IIS)を構築

FTPで外部連携するためのプログラムを開発する際に、接続先のFTPサーバの準備に困る場合があります。 ここでは、Widnwos10上に開発・検証用のFTPサーバを構築するための手順を説明します。 「I …

.NET Core: JsonSerializerの単純な使い方

JsonSerializerの基本的な使い方とサンプルを説明します。 概要 .NET Core 3.1の標準パッケージSystem.Text.Jsonに含まれるJsonSerializerを使って、ク …

Windowsの証明書ストアの基礎知識と確認方法

※証明書ストア、システムストア、物理ストアの厳密な定義や違いを読み解けなかったため、マイクロソフトのリファレンスを意訳して言葉を使用しています。 証明書ストアの基礎 証明書は「ローカルコンピューター」 …

JIS X 0208, Shift_JIS, Windows-31Jの整理

文字コードの話は難しそうなイメージがあり、必要になったタイミングでその都度、最小限の知識を習得して対応してきました…が、効率が悪く踏み込んだ話になった時に困る場合もあるので、ここで真面目に …