今さら聞けないJavaログ出力 – log4j入門

そこにログがあるじゃろ・・・? ( ^ω^)

→ いや、ない!(;゚д゚)

こんな事にはなりたくないものです。

プロジェクトが大規模になっていくと、障害におけるログファイルの解析はとても重要になります。

なのにロジック内で例外発生した際、catchした後ログを出力せずサイレントで終了するような書き方をしているロジックがまま見受けられます…。

開発プロセスにてログ出力が実装されていないと、システムエラーの原因が分からず、原因追究に多くの時間が割かれたりします。

そのようなロジックを解析する保守メンバーにはなりたくないものです。

プログラム実装の際には保守フェーズなども考え、設計書に無くてもログ出力を心がけるようにします。

Java界隈でのログ出力ライブラリは、そんなに発展の無い分野といえますが、それでもこれまでいくつかの変遷、トレンドを経てきました。

ログの出力方法のトレンドの移り変わりによりプロジェクトの発生したタイミングによって利用しているライブラリが異なることでしょう。

もっとも代表的なログ出力実装ライブラリ(ロガー)はlog4jではないでしょうか。

また、log4jのようなロガー(実装)を呼び出すためのアダプタとしてapache/commons-loggingが登場しました。

このアダプタライブラリを利用すれば、ログの出力実装をlog4jにするかjava.util.loggingにするか別のロガーライブラリにするかを開発フェーズと並走しながら柔軟に選択することができるようになりました。

しばらくは、log4j + commons-loggingトレンドが続いた後、log4jの開発者がログ出力のパフォーマンスを改善するためにlogback(ロガー)+SLF4J(アダプタ)を生みだし、Springプロジェクトが標準でそちらを採用するなどしたため、トレンドがそちらに移りました。

一方で、log4jもバージョン2(log4j2)が登場し、パフォーマンスが大幅に改善、JAVAログ出力界隈が混沌としてきました。

現在は、logback + SLF4J または log4j2 + SLF4J という組み合わせの2強といったところでしょうか。

とはいえ、ログ出力の勘所はどこでどのようなエラーが起こったかを解析者に明確に示せることであり、ロジックに対して過剰なパフォーマンスをかけないという点でもこれら2つは要件を満たしており、どちらを使うべきかという議論はあまり意味のないように感じます。

というわけで今回は個人的に知識のあるlog4j側を取り上げます。今更聞けないlog4jライブラリの基本を確認していきましょう。

log4jの実装

一般にlog4jの設定は、プロパティファイル、XMLファイル、YAMLファイルの3つの形式のうちいずれかを使って記述されます。
今回は私の触れる機会の多かったXML形式の設定ファイルで説明します。

log4j設定ファイルの基本的な書き方ですが、
・ログ出力先の定義
・ログ出力対象の定義
この2大要素を設定ファイルの中で作成し、関連づけることでログが出力されるようになります。

Springフレームワークを利用している場合などは、プロジェクトのリソースフォルダ直下にlog4j.xmlというXMLファイルを設置すると自動的に読み込まれます。
ただし、log4jバージョン2を利用している場合は、log4j2.xmlとなります。注意してください。

今回はlog4jバージョン2を使ったため、log4j2設定ファイル(XML)の例を掲載します。log4j(バージョン1)も基本的には同じ書き方です。

log4j2.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="off">
    <!-- ログの出力先と出力フォーマットを指定する -->
    <Appenders>
        <Console name="console-appender" target="SYSTEM_OUT">
            <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}]&#x9;%-5p&#x9;%C&#x9;%M&#x9;line:%L&#x9;%m%n"/>
        </Console>

        <RollingFile name="file-appender"
        		fileName="D:/Documents/java/logs/Err.log"
        		filePattern="D:/Documents/java/logs/ErrBAK-%d{yyyy-MM-dd}-%i.log">
            <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}]&#x9;%-5p&#x9;%C&#x9;%M&#x9;line:%L&#x9;%m%n"/>
            <Policies>
                <OnStartupTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="100 KB" />
            </Policies>
            <DefaultRolloverStrategy max="10"/>
        </RollingFile>
    </Appenders>

    <!-- パッケージごとにAppenderとログレベルを組み合わせる -->
    <Loggers>
        <Logger name="net.newbiz.ebil.webapp" level="trace">
            <AppenderRef ref="console-appender"/>
            <AppenderRef ref="file-appender" />
        </Logger>
        
        <Root level="info">
            <AppenderRef ref="console-appender"/>
        </Root>
    </Loggers>
</Configuration>

これがlog4j設定ファイルの基本形です。

必要なものは、Appender(ログ出力先)とLogger(ログ出力対象)です。

Appendarはログの出力先や出力形式を設定します。
上記ではAppendarを2つ定義していることになります。ConsoleタグとRollingFileタグがそれです。
Consoleタグでは標準出力、標準エラー出力に対してログ書き出しを行います。例ではSYSTEM_OUTを指定して標準出力を指定しています。また、PetternLayoutタグで出力の際の形式を指定しています。

[%d{yyyy-MM-dd HH:mm:ss.SSS}]&#x9;%-5p&#x9;%C&#x9;%M&#x9;line:%L&#x9;%m%n

%-5pは空白埋め5文字でログレベル(INFOなど)の文字列を出力、%Cはクラス名、%mがログメッセージ、%nは改行、&#x9;はタブ文字です。つまり、タブ文字区切りで各項目を出力しています。

ファイル出力には、Fileタグもありますが、RollingFileの方が高機能なのでそちらを使います。
OnStartupTriggeringPolicyタグは起動時にログファイルを洗い替えすること、SizeBasedTriggeringPolicyタグは指定したサイズに達した時点でログファイルを洗い替えることをそれぞれ指定しています。

DefaultRolloverStrategy タグはバックアップログの個数が指定した数を超えるとロールオーバー(古いものから削除)させることを指定。ここでは10個が保管するMAXファイル数となります。filePatternで指定したパスがローリングでバックアップとして保管されるファイルパス名になります。filePattern=”~~~.zip”、filePattern=”~~~.tar.gz”などと指定すると拡張子判断で自動的に圧縮してくれます。便利です。

一方、LoggerはJAVA側で指定したlog出力部に対してどのレベルを、どのAppenderに対して出力するかを指定するものです。

では一度、出力する側のJAVAソースを見てみましょう。

ログを出力するJAVAソース
package net.newbiz.ebil.webapp.billing;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.servlet.ModelAndView;

import net.newbiz.ebil.billing.service.iface.BillingCustomerSearchExecService;

@Controller
public class BillingSearchCustomerController {
	
	/** Logger SLF4J */
	private static org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(BillingSearchCustomerController.class);

	/** Logger log4j */
	private static org.apache.logging.log4j.Logger log4j = org.apache.logging.log4j.LogManager.getLogger(BillingSearchCustomerController.class);
	
	@Autowired
	private BillingCustomerSearchExecService billingCustomerSearchExecService;
	
	public void setBillingCustomerSearchExecService(BillingCustomerSearchExecService billingCustomerSearchExecService)
	{
		this.billingCustomerSearchExecService = billingCustomerSearchExecService;
	}
	
	@RequestMapping("/billing")
	public ModelAndView execBillingCustomerSearch(
				@RequestParam(value="aaa", required=false)boolean aaa,
				ModelAndView mav)
	{
		// SLF4J
		log.trace("すぐやる");
		log.debug("いまやる");
		log.info("できるまでやる");
		log.warn("できる方法をさがす");
		log.error("そのための知識を身につけておく");
		
		mav.setViewName("billing/BillingSearchCustomer");
		return mav;
	}
}

ログに関わる部分は15~18行目、および34~38行目です。
このソース上では指定方法の例としてslf4j、log4jの両方をロガーとして呼べるように生成していますが、実際はslf4jのみを指定するのをオススメします。
前述のとおり、slf4jはロガー(実装)を呼び出すためのアダプターです。
ロガーの実装をlog4jからlogbackなどに変更したい場合もソースに影響を与えず実行環境側のみで切り替えることができるからです。
(ただしlog4jを直接呼び出す方がパフォーマンスは有利です。微々たるものですがw)

また、ログのレベルは以下の順に高くなります。
trace
debug
info
warn
error
(fatal) ・・・log4jネイティブでは存在。SLf4Jを介す場合は指定不可。
設定ファイル側のログ出力レベルを低く設定しておけば、それより高いレベルのものはすべて出力することになります。
各ログレベルに関しては以下のような取り決めが一般的です。

ログレベル 用途
fatal システムがこれ以上動作できない致命的なエラーが発生した場合
error 予期せぬ動作などにより、正しく処理できない場合
warn なんらかの問題が発生したが、動作には影響がない場合
info 設定ファイルを読み込んだときの設定情報、システム開始/停止時の状態出力など
debug デバッグ情報。例えば、外部モジュールから呼ばれるメソッドの入出力情報など
trace 詳細なデバッグ情報。モジュール内部の情報、ループの繰り返しで大量に出力される情報など

http://www.atmarkit.co.jp/ait/articles/0308/23/news001.html

では、Javaを実行してみましょう。

[2016-06-29 15:08:32.000] TRACE net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:34 すぐやる
[2016-06-29 15:08:32.001] DEBUG net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:35 いまやる
[2016-06-29 15:08:32.001] INFO net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:36 できるまでやる
[2016-06-29 15:08:32.002] WARN net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:37 できる方法をさがす
[2016-06-29 15:08:32.002] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:38 そのための知識を身につけておく

記述したメッセージがすべてログ”D:/Documents/java/logs/Err.log”に出力されました。

では次に、net.newbiz.ebil.webappパッケージに対するLoggerのlevelをinfoに指定してみましょう。

        <Logger name="net.newbiz.ebil.webapp" level="trace">
            <AppenderRef ref="console-appender"/>
            <AppenderRef ref="file-appender" level="info"/>
        </Logger>

再びJavaを実行してみましょう。

[2016-06-29 15:22:26.071] INFO net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:36 できるまでやる
[2016-06-29 15:22:26.072] WARN net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:37 できる方法をさがす
[2016-06-29 15:22:26.073] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:38 そのための知識を身につけておく

file-appenderアペンダー、つまり”D:/Documents/java/logs/Err.log”に対してInfo以上のログのみが出力されるようになりましたね。

ここでLoggersの中に指定されているRootタグについて明記しておきます。Rootタグとは何か。

Rootタグを指定するとRootロガーが生成されます。このRootロガーはすべてのロガーに対する最上位ロガーです。というとちょっとわかりずらいと思いますが、要は”基本的にはすべてのログ出力に適用されるもの”と思ってください。

すなわち、この例の場合、Javaのログ出力ロジック1行に対して1つ目のロガーとルートロガーによる出力がされることになります。

このため、コンソール側のログ出力を確認すると

[2016-06-29 15:40:31.620] TRACE net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:34 すぐやる
[2016-06-29 15:40:31.620] TRACE net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:34 すぐやる
[2016-06-29 15:40:31.621] DEBUG net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:35 いまやる
[2016-06-29 15:40:31.621] DEBUG net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:35 いまやる
[2016-06-29 15:40:31.622] INFO net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:36 できるまでやる
[2016-06-29 15:40:31.622] INFO net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:36 できるまでやる
[2016-06-29 15:40:31.622] WARN net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:37 できる方法をさがす
[2016-06-29 15:40:31.622] WARN net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:37 できる方法をさがす
[2016-06-29 15:40:31.623] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:38 そのための知識を身につけておく
[2016-06-29 15:40:31.623] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:38 そのための知識を身につけておく

このように無駄にダブって出力されるわけです。
一方で”net.newbiz.ebil.webapp”配下以外のパッケージでログ出力した場合、ルートロガーのみが適用される事になります。

しかしこのままだと”net.newbiz.ebil.webapp”配下のパッケージのログ出力が無駄に感じますよね。そこでこのように記述します。

    <Loggers>
        <Logger name="net.newbiz.ebil.webapp" level="trace" additivity="false">
            <AppenderRef ref="console-appender"/>
            <AppenderRef ref="file-appender" level="info"/>
        </Logger>
        
        <Root level="info">
            <AppenderRef ref="console-appender"/>
        </Root>
    </Loggers>

additivity=”false”という記述がポイントです。
これによって上位へのログ出力指令を止めることができます。つまり、”net.newbiz.ebil.webapp”パッケージに対しては1番目のロガーのみが適用されることになります。

[2016-06-29 15:49:44.194] INFO org.thymeleaf.TemplateEngine initialize line:838 [THYMELEAF] TEMPLATE ENGINE INITIALIZED
[2016-06-29 15:49:49.008] TRACE net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:34 すぐやる
[2016-06-29 15:49:49.009] DEBUG net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:35 いまやる
[2016-06-29 15:49:49.009] INFO net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:36 できるまでやる
[2016-06-29 15:49:49.009] WARN net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:37 できる方法をさがす
[2016-06-29 15:49:49.010] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:38 そのための知識を身につけておく

ダブらないよう出力することができました。

次にあるログメッセージのみ、別のログファイルにのみ出すよう切り分ける方法です。

...
	/** Logger SLF4J(追加ロガー) */
	private static org.slf4j.Logger logB = org.slf4j.LoggerFactory.getLogger("tafujiDevLogger");
...
		// SLF4J
		log.trace("すぐやる");
		log.debug("いまやる");
		log.info("できるまでやる");
		log.warn("できる方法をさがす");
		log.error("そのための知識を身につけておく");
		
		// 追加ロガー
		logB.debug("このメッセージは切り分けて出したいんです");

ご覧のように、getLoggerの引数として指定するのはクラスオブジェクトである必要はありません。これはlog4jのカテゴリ名と呼ばれるもので、この文字列がlog4j.xmlに記載されているロガーのname属性と比較され、マッチしたロガーが取得される仕組みです。
一般にカテゴリ名=パッケージというような記述の設定がよく用いられるためあまり知られていないのではないでしょうか。

        ...
        <!-- 追加 -->
        <RollingFile name="devlog"
        		fileName="D:/Documents/java/logs/devlog.log"
        		filePattern="D:/Documents/java/logs/devlog-%d{yyyy-MM-dd}-%i.log">
            <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}]&#x9;%-5p&#x9;%C&#x9;%M&#x9;line:%L&#x9;%m%n"/>
            <Policies>
                <OnStartupTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="100 KB" />
            </Policies>
            <DefaultRolloverStrategy max="10"/>
        </RollingFile>
        ...
        <!-- 追加 -->
        <Logger name="tafujiDevLogger" level="trace" additivity="false">
            <AppenderRef ref="devlog"/>
        </Logger>
        ...

これによって上で指定したログメッセージは”D:/Documents/java/logs/devlog.log”のみに出力されるようになります。

■ 出力結果

[2016-06-29 16:13:40.357] DEBUG net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:44 このメッセージは切り分けて出したいんです

設定ファイル上の注意点としてログレベルの設定があります。
仮に以下のように設定したとしましょう。

        <Logger name="net.newbiz.ebil.webapp" level="error" additivity="false">
            <AppenderRef ref="console-appender"/>
            <AppenderRef ref="file-appender" level="info"/>
        </Logger>

Loggerタグで指定したlevelとAppenderRefで指定したlevelで順位がテレコになっています。この場合、Loggerタグで指定したレベルが優先されるため、出力結果はこうなります。

[2016-06-29 16:17:07.001] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:41 そのための知識を身につけておく

このように、infoレベルのログは出力されていません。

Loggerの中でレベルごとに出力するログファイルを分けるなどする場合、このレベルの指定には注意が必要です。

Javaコード側について

一方、
Java側の記述方法ですが、可変文字列を差し込みたい場合は以下のように記述することができます。

		String obj1 = "計算処理";
		log.error("{}で{}のエラーが発生しました", obj1, "想定外");
		log.error("{}で{}のエラーが発生しました", new String[]{obj1, "想定内"});

■ 出力結果

[2016-06-29 16:27:22.887] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:47 計算処理で想定外のエラーが発生しました
[2016-06-29 16:27:22.887] ERROR net.newbiz.ebil.webapp.billing.BillingSearchCustomerController execBillingCustomerSearch line:48 計算処理で想定内のエラーが発生しました

また、エラーログ出力の基本ですが、想定外の例外エラーが発生した場合には例外トレースを出すようにしておきましょう。


		try
		{
			throw new RuntimeException("まさかの例外発生ッ!Σ(゜□゜");
		}
		catch (Exception e)
		{
			log.error("システムエラー", e);
		}

2番目の引数にExceptionオブジェクトを渡します。

出力結果は以下。

java.lang.RuntimeException: まさかの例外発生ッ!Σ(゜□゜
at net.newbiz.ebil.webapp.billing.BillingSearchCustomerController.execBillingCustomerSearch(BillingSearchCustomerController.java:52) [classes/:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_91]
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_91]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_91]
at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_91]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221) [spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]

これによってエラー発生箇所がログファイルを見ただけで解析できるようになります。
くれぐれもcatch{}ブロック内で例外を握りつぶさず、ログ出力のロジックを入れましょう。上位がログ出力を行ってくれるならばthrowすべきケースもあるのでそこは適宜判断の上実装してください。

もっと詳しく設定ファイルを知りたければ、本家サイトなど参考にしてください。
http://logging.apache.org/log4j/2.x/manual/configuration.html

それではよいログライフを。( ^ω^)

カテゴリー: Java

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です