Javaのロギングライブラリですが、
と種々あり、最近ではSLF4J＋Logbackが主流な気がするのですが、自分の周りでは長らくLog4j、またはCommons Loggin越しにLog4jのパターンが多かったです。というか、今もですが。
Log4jの上に、自作のロギングライブラリを作ることになることも、多々…。
まあ、そんな感じで昨今のJavaのロギング事情にだいぶ置いていかれているのですが、ここでちょっとLog4jの後継であるLog4j2を試してみたくなりまして。
Apache Log4j2
http://logging.apache.org/log4j/2.x/
なんでも、パフォーマンスがかなり良くて有名？らしいのですが。
The Logging Olympics – A Race Between Today’s Top 5 Java Logging Frameworks
http://www.takipiblog.com/2013/12/18/the-logging-olympics-a-race-between-todays-top-5-logging-frameworks/
Performance
http://logging.apache.org/log4j/2.x/performance.html
ちなみに、2012年7月にアルファ版がMaven Centralにアップされて、2014月にRC2と、かなり開発版の状態が長い感じもします。開発は進んでいるようなので、いいのですが。
前身のLog4jとはAPIに互換性はありませんが、前述したようにパフォーマンスが高い、APIと実装が分離されている、他のロギングライブラリとのブリッジが別コンポーネントとして存在するなど、いろいろ進化しています。
今回は、基本的な使い方をさらさらと眺めてみます。
Maven依存関係
Log4j2を単体で使う場合は、以下の依存関係を追加します。
<dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-api</artifactId> <version>2.0-rc2</version> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-core</artifactId> <version>2.0-rc2</version> </dependency>
まあ、Coreを入れるとAPIも付いてきますけどね…。
参考）
Maven and Ivy Artifacts
http://logging.apache.org/log4j/2.x/maven-artifacts.html
設定
Configuration
http://logging.apache.org/log4j/2.x/manual/configuration.html
ファイル名は、log4j2.xmlやlog4j2.jsonで。
今回はXMLファイルで、以下のような形で用意しました。
src/main/resources/log4j2.xml
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="WARN"> <Appenders> <Console name="Console" target="SYSTEM_OUT"> <PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level - %msg%n"/> </Console> </Appenders> <Loggers> <Root level="trace"> <AppenderRef ref="Console"/> </Root> </Loggers> </Configuration>
あとで、少しPatternLayoutは変えていきます。
PatternLayout
http://logging.apache.org/log4j/2.x/manual/layouts.html#PatternLayout
初めてのLog4j2
では、Log4j2を使ってログ出力をしてみます。
以降のJavaコードでは、少なくとも以下のimport文が宣言されているものとします。
import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.LogManager;
Log4j2を使用して、ログ出力を行うコード。
Logger logger = LogManager.getLogger(Log4j2Example.class); logger.trace("TraceMessage"); logger.debug("DebugMessage"); logger.info("InfoMessage {}!", "Hello Log4j2"); logger.warn("WarnMessage {}!", "Hello Log4j2"); logger.error("ErrorMessage"); logger.fatal("FatalMessage"); logger.info("Exception", new IllegalArgumentException("Oops!"));
こんな感じで、「{}」を使うことで後続の引数の値をログに埋め込むことができるそうですが、ログ出力対象でなかったレベルの場合は、メッセージの組み立てが行われないそうです。
logger.info("InfoMessage {}!", "Hello Log4j2");
デバッグログ出力時に、こういうことをしなくてもよい、と。
if (logger.isDebugEnabled()) { logger.debug("Logging in user " + user.getName() + " with birthday " + user.getBirthdayCalendar()); }
SLF4Jでも同じことができるそうなので、そんなに目新しい話しでもないのかも…。
Log4j 2 API Overview
http://logging.apache.org/log4j/2.x/manual/api.html
先ほどのコードの実行して出力されるログは、こんな感じになります。
2014/06/28 21:05:13.743 TRACE - TraceMessage 2014/06/28 21:05:13.764 DEBUG - DebugMessage 2014/06/28 21:05:13.771 INFO - InfoMessage Hello Log4j2! 2014/06/28 21:05:13.772 WARN - WarnMessage Hello Log4j2! 2014/06/28 21:05:13.773 ERROR - ErrorMessage 2014/06/28 21:05:13.773 FATAL - FatalMessage 2014/06/28 21:05:13.773 INFO - Exception java.lang.IllegalArgumentException: Oops! at org.littlewings.log4j2.Log4j2Example.simple(Log4j2Example.java:26) [classes/:?] at org.littlewings.log4j2.Log4j2Example.main(Log4j2Example.java:9) [classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_05] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_05] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_05] at java.lang.reflect.Method.invoke(Method.java:483) ~[?:1.8.0_05] at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293) [exec-maven-plugin-1.3.jar:?] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_05]
なんか、スタックトレースにどのクラスがどこからロードされたか出ているのが、ちょっとスゴいと思ったり。
ここで、PatternLayoutをこのようにすると
＊最後に「%ex」を付けています
<PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level - %msg%n%ex"/>
スタックトレースに、ロード元が出なくなります。
2014/06/28 21:09:15.882 INFO - Exception java.lang.IllegalArgumentException: Oops! at org.littlewings.log4j2.Log4j2Example.simple(Log4j2Example.java:26) at org.littlewings.log4j2.Log4j2Example.main(Log4j2Example.java:9) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:483) at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293) at java.lang.Thread.run(Thread.java:745)
「%ex」は、付けた方がパフォーマンス的にはいいのかな…？
また、「%ex」ですが、以下の様に{}の中に数字を入れることで
<PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level - %msg%n%ex{3}"/>
出力されるスタックトレースの行を絞ることができます。
2014/06/28 21:13:24.288 INFO - Exception java.lang.IllegalArgumentException: Oops! at org.littlewings.log4j2.Log4j2Example.simple(Log4j2Example.java:26) at org.littlewings.log4j2.Log4j2Example.main(Log4j2Example.java:9)
ですが、この後のログがスタックトレースの後につながっちゃったり…。
ThreadContext
Log4jでいうNDC、MDCは、ThreadContextというクラスに統合されたようです。
Log4j 2 API Thread Context
http://logging.apache.org/log4j/2.x/manual/thread-context.html
利用するには、以下のimport文を加えます。
import org.apache.logging.log4j.ThreadContext;
まずは、NDCの代替から紹介します。
今回のPatternLayoutは、このようにしておきます。
<PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level %x - %msg%n"/>
「%x」が入りました。
利用するJavaコード。
Logger logger = LogManager.getLogger(Log4j2Example.class); ThreadContext.push("push1"); logger.info("InfoMessage1"); ThreadContext.push("push2"); logger.info("InfoMessage2"); ThreadContext.pop(); logger.info("InfoMessage3"); ThreadContext.pop(); logger.info("InfoMessage4"); // スタックをクリアする場合は、ThreadContext#clearStack ThreadContext.clearStack(); // ThreadContext.clearAll(); // こちらでも可 logger.info("InfoMessage5");
出力結果。
2014/06/28 21:19:58.911 INFO [push1] - InfoMessage1 2014/06/28 21:19:58.911 INFO [push1, push2] - InfoMessage2 2014/06/28 21:19:58.911 INFO [push1] - InfoMessage3 2014/06/28 21:19:58.911 INFO [] - InfoMessage4 2014/06/28 21:19:58.912 INFO [] - InfoMessage5
「%x」の部分に、ThreadContext#pushした値が[]付きで入るようになり、popすると減っていきます。
ThreadContextにpushした後始末は、ThreadContext#clearStackまたはclearAllを呼び出します。
// スタックをクリアする場合は、ThreadContext#clearStack ThreadContext.clearStack(); // ThreadContext.clearAll(); // こちらでも可
clearAllの場合は、後述のputを使用したものもクリアします。
ThreadContextが持つスタックが空の状態でpopしたりすると、エラーになります。
なお、ThreadContext#clearStack、clearAll、そしてこの後紹介するclearMapは、RC2で登場したメソッドで、それまではThreadContext#clearでした…。ドキュメント上もまだclearのままなので、その点ご注意を。
使用するPatternLayoutは、このようにします。
<PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level %X %X{id} %X{ipAddress} - %msg%n"/>
「%X」または「%X{key}」を指定します。
利用側のJavaコード。
Logger logger = LogManager.getLogger(Log4j2Example.class); ThreadContext.put("id", "user0001"); ThreadContext.put("ipAddress", "127.0.0.1"); logger.info("InfoMessage"); ThreadContext.clearMap(); // ThreadContext.clearAll(); // こちらでも可（Stackも一緒にクリアする） logger.info("InfoMessage");
実行結果。
2014/06/28 21:28:12.599 INFO {id=user0001, ipAddress=127.0.0.1} user0001 127.0.0.1 - InfoMessage
2014/06/28 21:28:12.599 INFO {} - InfoMessage「%X」には、ThreadContext#putした値がすべて入り、「%X{key}」では指定したキーに対応する値が出力されます。
クリアは、ThreadContext#clearMapまたはclearAllで。clearAllの場合は、前述のスタックも破棄されます。
Flow Tracing
メソッドのIn／Outなど、各種トレースの際に使えるちょっと便利なメソッド。
Log4j 2 API Flow Tracing
http://logging.apache.org/log4j/2.x/manual/flowtracing.html
PatternLayoutは、こちらを使用します。
<PatternLayout pattern="%d{yyy/MM/dd HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%n"/>
「%class」や「%L」、「%M」を指定することで、クラス名やメソッド名、行数が出力されますが、パフォーマンスも落ちるのでご利用はほどほどに。
Location Information
http://logging.apache.org/log4j/2.x/manual/layouts.html#LocationInformation
単純な利用例。ここは、メソッド定義のイメージで書いた方がいいですね。
private static void tracing1() { Logger logger = LogManager.getLogger(Log4j2Example.class); logger.entry(); logger.info("InfoTracing"); logger.exit(); }
結果。
2014/06/28 21:36:46.133 TRACE org.littlewings.log4j2.Log4j2Example 67 tracing1 - entry 2014/06/28 21:36:46.133 INFO org.littlewings.log4j2.Log4j2Example 69 tracing1 - InfoTracing 2014/06/28 21:36:46.133 TRACE org.littlewings.log4j2.Log4j2Example 71 tracing1 - exit
だから？みたいな。
が、Logger#entryやexitメソッドは、引数を取ることができます。このように。
private static String tracing2(String param1, int param2) { Logger logger = LogManager.getLogger(Log4j2Example.class); logger.entry(param1, param2); logger.info("InfoTracing"); return logger.exit("Method Return Value2"); }
exitは、引数をそのまま戻します。
このtracing2メソッドを、こう呼び出したとします。
tracing2("Message1", 100);
結果。
2014/06/28 21:39:32.436 TRACE org.littlewings.log4j2.Log4j2Example 76 tracing2 - entry params(Message1, 100) 2014/06/28 21:39:32.436 INFO org.littlewings.log4j2.Log4j2Example 78 tracing2 - InfoTracing 2014/06/28 21:39:32.437 TRACE org.littlewings.log4j2.Log4j2Example 80 tracing2 - exit with(Method Return Value2)
トレース結果に、メソッドの引数や戻り値を出力することができます。
さらに、例外のスロー、捕捉用のメソッドもあります。
private static String tracing3(String param1, int param2) { Logger logger = LogManager.getLogger(Log4j2Example.class); logger.entry(param1, param2); try { logger.info("InfoTracing"); throw logger.throwing(new IllegalArgumentException("Oops!")); } catch (Exception e) { logger.catching(e); } return logger.exit("Method Return Value3"); }
今回は自分で投げてキャッチしているのでムダですが、結果はこうなります。
2014/06/28 21:41:42.459 TRACE org.littlewings.log4j2.Log4j2Example 85 tracing3 - entry params(Message2, 300) 2014/06/28 21:41:42.459 INFO org.littlewings.log4j2.Log4j2Example 88 tracing3 - InfoTracing 2014/06/28 21:41:42.459 ERROR org.littlewings.log4j2.Log4j2Example 89 tracing3 - throwing java.lang.IllegalArgumentException: Oops! at org.littlewings.log4j2.Log4j2Example.tracing3(Log4j2Example.java:89) [classes/:?] at org.littlewings.log4j2.Log4j2Example.main(Log4j2Example.java:14) [classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_05] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_05] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_05] at java.lang.reflect.Method.invoke(Method.java:483) ~[?:1.8.0_05] at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293) [exec-maven-plugin-1.3.jar:?] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_05] 2014/06/28 21:41:42.460 ERROR org.littlewings.log4j2.Log4j2Example 91 tracing3 - catching java.lang.IllegalArgumentException: Oops! at org.littlewings.log4j2.Log4j2Example.tracing3(Log4j2Example.java:89) [classes/:?] at org.littlewings.log4j2.Log4j2Example.main(Log4j2Example.java:14) [classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_05] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_05] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_05] at java.lang.reflect.Method.invoke(Method.java:483) ~[?:1.8.0_05] at org.codehaus.mojo.exec.ExecJavaMojo$1.run(ExecJavaMojo.java:293) [exec-maven-plugin-1.3.jar:?] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_05] 2014/06/28 21:41:42.460 TRACE org.littlewings.log4j2.Log4j2Example 94 tracing3 - exit with(Method Return Value3)
Logger#throwingとcachingの両方を使った分だけ、ログが2倍出ていますが…。
その他、Markerや他のロギングライブラリとの連携機能もあり、なかなかよさそうです。正式版はいつ出るのでしょうか？
また、個人的にはJBoss Loggingと合わせて使ってみたいですね。
