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

主に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

執筆者:

関連記事

OWASPが推奨する強力なパスワード

Webアプリケーションのセキュリティの標準化や推進を行うOWASPでは、強力なパスワードの使用を推奨しているので、それをまとめた。 cheatsheetseries.owasp.orgAuthenti …

postgresqlでの拡張のインストール

PostgreSQL10で暗号化関数を使用するため拡張(pgcrypto)をインストールした際の出来事を記載します。 事象 pgcryptoの拡張をインストールしたり、インストールの確認を行うと、その …

ASP.NET Core: IHttpClientFactoryのサンプル

前回の記事でIHttpClientFactoryの使用方法を説明しました。 ここでは、サンプルを使用した具体的な使用方法を説明します。 前提 マイクロソフトが推奨するIHttpClientFactor …

SLF4Jの仕組みと使用方法

何気に使用しているSLF4Jの仕様やその仕組みを整理したいと思います。 前提 元ネタはSLF4J Manualサイトです。 2019年1月での安定版の最新である1.7.25を使用した例を記載します。 …

Javaでサポートする暗号化アルゴリズム

Java暗号化アーキテクチャ Javaで暗号化処理を実装する場合、Java暗号化アーキテクチャ(Java Cryptography Architecture: JCA)と呼ばれるフレームワークを使いま …

プロフィール ゆっきーです。
都内でシステムエンジニアをやっています。
もっと詳細を見る