log4j2をYAML＋Gradleで使用する #Java

Javaのロガーを物色していたところ log4j2 は設定ファイルをYAMLで書けると聞いたので試してみました。しかし、動作させるのに予想以上にハマったのでYAMLで動かすための方法をまとめておきます。
なお、XMLは人類が読み書きするフォーマットだと思っていないのでMavenではなく、Gradleを利用してサンプルアプリケーションを作成しています。

追記

YAMLの設定とログ出力を追記しました(2017年1月30日)

log4j2.ymlが読み込まれない

Log4j2 の設定を YAML で書く, Spring Boot でも使ってみるを参考に以下の作業を行い、ログ出力を行ってみました。

src/main/resources フォルダ下に log4j2.yml を配置
build.gradle に以下の依存関係を追加

dependencies {
    compile('org.apache.logging.log4j:log4j-core:2.7')
    compile('org.apache.logging.log4j:log4j-api:2.7')

    compile('com.fasterxml.jackson.dataformat:jackson-dataformat-yaml:2.8.5')
}

しかし、以下のエラーログが無情に出力され続けます。エラーログの文言でググっても、 Stack Overflow をしらみつぶしに探しても解決方法は見つかりませんでした。

ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.

結論

依存関係に jackson-core と jackson-databind が必要でした。
build.gradle の記述は以下が正解です。
サンプルコードをこちらに公開しておりますので必要であれば参考にしてください。

dependencies {
    compile('org.apache.logging.log4j:log4j-core:2.7')
    compile('org.apache.logging.log4j:log4j-api:2.7')

    compile('com.fasterxml.jackson.dataformat:jackson-dataformat-yaml:2.8.5')
    compile('com.fasterxml.jackson.core:jackson-core:2.8.5')
    compile('com.fasterxml.jackson.core:jackson-databind:2.8.5')
}

YAMLの設定とログ出力

参考までにシンプルなYAMLの設定例です。パッケージ階層に応じたログレベルでコンソールにログを出力します。

Configuration:
  status: debug

  Appenders:
    Console:
      name: CONSOLE
      target: SYSTEM_OUT
      PatternLayout:
        Pattern: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %c{3} - %msg%n"

  Loggers:
    Logger:
      - name: cobot00.gs.first
        additivity: false
        level: warn
        AppenderRef:
          - ref: CONSOLE
      - name: cobot00.gs.first.second
        additivity: false
        level: info
        AppenderRef:
          - ref: CONSOLE
    Root:
      level: debug
      AppenderRef:
        ref: CONSOLE

上記のようなパッケージ、クラス階層だと以下のようにログが出力されます。

2017-01-30 22:56:49.007 [main] WARN  gs.first.FirstLayer - warning
2017-01-30 22:56:49.008 [main] ERROR gs.first.FirstLayer - error

2017-01-30 22:56:49.010 [main] INFO  first.second.SecondLayer - SecondLayer(number=2, tag=Gradle)
2017-01-30 22:56:49.011 [main] WARN  first.second.SecondLayer - warning
2017-01-30 22:56:49.011 [main] ERROR first.second.SecondLayer - error

2017-01-30 22:56:49.013 [main] INFO  second.third.ThirdLayer - ThirdLayer(number=3, tag=YAML)
2017-01-30 22:56:49.013 [main] WARN  second.third.ThirdLayer - warning
2017-01-30 22:56:49.013 [main] ERROR second.third.ThirdLayer - error

謎解き編

どうやって依存関係の欠落に気づいたのかの解説です。Java中級以上の方向けの内容になるかと思います。

そもそもパスが通っているのか？

log4j2.yml が読み込まれない理由としては以下が考えられます。

設定ファイルのディレクトリにパスが通っていない
人知を超えた何かが不足している

まずは 1 のケースを検証するために log4j2.yml を log4j2.xml にリネームしてみます。すると、以下の例外が発生します。

[Fatal Error] log4j2.xml:1:1: プロローグにはコンテンツを指定できません。
ERROR StatusLogger Error parsing C:\coding\workspace\log4j2simple\bin\log4j2.xml
 org.xml.sax.SAXParseException; systemId: file:///C:/coding/workspace/log4j2simple/bin/log4j2.xml; lineNumber: 1; columnNumber: 1; プロローグにはコンテンツを指定できません。
  at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(Unknown Source)
  at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(Unknown Source)
  at org.apache.logging.log4j.core.config.xml.XmlConfiguration.<init>(XmlConfiguration.java:96)
  at org.apache.logging.log4j.core.config.xml.XmlConfigurationFactory.getConfiguration(XmlConfigurationFactory.java:46)
  at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:519)
(後略)

log4j2.xml だと認識されてXMLとしてパースが実行されるようです。
気になるのは以下のログです。 ConfigurationFactory クラスを調べれば何か手がかりが得られるのではないでしょうか？

org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:519)

log4j2のソースコードを調べよう

log4j2 ConfigurationFactory をキーワードにググってヒットしたものを眺めていると https://github.com から始まるURLの記事が見つかります。リンク先からリポジトリのメインページに移ってCloneのためのURLを確認し、 git clone の実行です。

git clone git@github.com:apache/logging-log4j2.git

プロジェクトを眺めると pom.xml が存在するのでeclipseにインポートするために以下のMavenコマンドを実行します。

mvn eclipse:eclipse

eclipseにMavenプロジェクトとしてインポートしたら ConfigurationFactory クラスとその周辺を確認すると config パッケージ下に json xml yaml といかにもなパッケージが存在するのに気づきます。

yaml パッケージ内に YamlConfigurationFactory クラスが存在します。
YamlConfigurationFactory の実装を眺めると冒頭から答えらしきものが目に入ってきます。
dependencies 変数で定義されているクラスが全て揃わないと YamlConfigurationFactory は有効にはならないようです。 com.fasterxml.jackson.databind com.fasterxml.jackson.core が依存関係に含まれるように build.gradle を修正すると例のエラーログは無くなり、 log4j2.yml で設定した内容でログが出力されるようになりました。

private static final String[] dependencies = new String[] {
    "com.fasterxml.jackson.databind.ObjectMapper",
    "com.fasterxml.jackson.databind.JsonNode",
    "com.fasterxml.jackson.core.JsonParser",
    "com.fasterxml.jackson.dataformat.yaml.YAMLFactory"
};

private final boolean isActive;

public YamlConfigurationFactory() {
    for (final String dependency : dependencies) {
        if (!Loader.isClassAvailable(dependency)) {
            LOGGER.debug("Missing dependencies for Yaml support");
            isActive = false;
            return;
        }
    }
    isActive = true;
}

追加の検証

YAMLの設定ファイルが読み込まれるようになったものの何故このような実装になっているのか気になります。ロガーの設定ファイルの読み込み、解釈の要になっている ConfigurationFactory.java を中心に処理の流れを追ってみました。
大まかに言うと対応している拡張子に対して優先順位に従って総当たりでファイル存在チェックをし、最初にヒットした設定ファイルを利用するという実装になっていました。
以下は拡張子の優先順位です。

設定ファイルの拡張子の優先順位

priority	extension
1	.properties
2	.yml
3	.yaml
4	.json
5	.jsn
6	.xml

テスト実行時はテスト用のファイルを優先するためにファイル名に test を含むものを考慮するようになっています。拡張子の優先順位とテスト用ファイルを考慮にいれると最終的には以下の順でファイル存在チェックを実行します。
そして YAML と JSON に関してはパースのために追加のクラスが必要になるため、Factoryクラスで依存関係チェックをし、必要なライブラリが全て揃っていない場合は設定ファイルが存在しても無視されるという実装になっています。このため log4j2.xml は読み込まれるが log4j2.yml や log4j2.json が無視されるという状況が発生しえます。

設定ファイル名の優先順位

priority	config file name
1	log4j2-test.properties
2	log4j2-test.yml
3	log4j2-test.yaml
4	log4j2-test.json
5	log4j2-test.jsn
6	log4j2-test.xml
7	log4j2.properties
8	log4j2.yml
9	log4j2.yaml
10	log4j2.json
11	log4j2.jsn
12	log4j2.xml

依存ライブラリのチェックは以下の実装になっているのですがログレベルの関係か Missing dependencies for Json support は出力されないようです。このログを出力させるには別の設定が必要なようですね・・・。

for (final String dependency : dependencies) {
    if (!Loader.isClassAvailable(dependency)) {
        LOGGER.debug("Missing dependencies for Json support");
        isActive = false;
        return;
    }
}