log4j2をYAML＋Gradleで使用する

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

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

## log4j2.ymlが読み込まれない

[Log4j2 の設定を YAML で書く, Spring Boot でも使ってみる](http://blog.rakugakibox.net/entry/2015/04/06/log4j2-yaml) を参考に以下の作業を行い、ログ出力を行ってみました。

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

```groovy
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` をしらみつぶしに探しても解決方法は見つかりませんでした。

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

## 結論

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

```groovy
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')
}
```

<a name="configuration_sample"></a>
## YAMLの設定とログ出力

参考までにシンプルな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
```

![layer.png](https://qiita-image-store.s3.amazonaws.com/0/106217/5bc145f8-abed-0e19-d14a-f5d2baae11b0.png)

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

```
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. 設定ファイルのディレクトリにパスが通っていない
2. 人知を超えた何かが不足している

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

```java
[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の [記事](https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationFactory.java) が見つかります。リンク先からリポジトリのメインページに移ってCloneのためのURLを確認し、 `git clone` の実行です。

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

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

```bash
mvn eclipse:eclipse
```

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

![config.png](https://qiita-image-store.s3.amazonaws.com/0/106217/b4b7754c-790a-f9a3-b6e8-6914f584ed95.png)

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

```java
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](https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/config/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` は出力されないようです。このログを出力させるには別の設定が必要なようですね・・・。

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