Javaプロジェクトでlogbackを使ったロギング、ハマった末にappenderのadditivityを知る

はじめに

最近学んだJavaのloggingについてです。
素振りのために用意したプロジェクト（SLF4J + logback）を使っていきます。

logback.xmlでconfiguration!

「Configuration with logback-test.xml or logback.xml」を参考に設定します。

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%kvp- %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="org.example" level="INFO">
        <appender-ref ref="STDOUT"/>
    </logger>
</configuration>

org.exampleロガーに、INFO以上を標準出力にロギングするように設定しました。

org.example.Mainクラスのmain()メソッドを実行します。

// https://nikkie-ftnext.hatenablog.com/entry/start-java-slf4j-logback-project のものです
public class Main {
    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(Main.class);
        logger.info("Start");
        System.out.println("Hello world!");
        logger.debug("End");
    }
}

21:38:04.335 [main] INFO  org.example.Main -- Start
Hello world!

org.example.Mainクラスのロガーはorg.exampleロガーの子にあたります。
子ロガーにレベルを設定していないので、org.exampleロガー同様にINFO以上をロギングします¹。
そのため、INFOのみ出力されています（DEBUGは出力されません）

ファイルに出力するappenderを追加

In logback speak, an output destination is called an appender. (Appenders and Layouts (Chapter 2: Architecture))

意訳 logbackの用語で言えば、出力先はappenderと呼ばれます。

上のconfigurationではConsoleAppenderを使って出力しました。
https://logback.qos.ch/manual/appenders.html#ConsoleAppender

RollingFileAppenderも使ってみます。
https://logback.qos.ch/manual/appenders.html#RollingFileAppender

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%kvp- %msg%n</pattern>
        </encoder>
    </appender>
+    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
+        <file>logFile.log</file>
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+            <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
+            <maxHistory>7</maxHistory>
+        </rollingPolicy>
+        <encoder>
+            <pattern>%d %-5level [%thread] %logger{0}: %msg%n</pattern>
+            <outputPatternAsHeader>true</outputPatternAsHeader>
+        </encoder>
+    </appender>

    <logger name="org.example" level="INFO">
        <appender-ref ref="STDOUT"/>
    </logger>
+    <logger name="org.example.Main" level="DEBUG">
+        <appender-ref ref="FILE"/>
+    </logger>
</configuration>

org.exampleロガーに、INFO以上を標準出力にロギングするように設定（変更なし）
org.example.Mainロガーには、DEBUG以上をファイルにロギングするように設定
- 後述しますが、これは思い込みから誤解があります

あれ？標準出力にDEBUGログも出力されてる

logFile.logには、DEBUG以上のログが記録されていて、期待通りです。

#logback.classic pattern: %d %-5level [%thread] %logger{0}: %msg%n
2024-07-09 21:48:47,416 INFO  [main] Main: Start
2024-07-09 21:48:47,416 DEBUG [main] Main: End

ところが、標準出力の方も見てみると

21:48:47.416 [main] INFO  org.example.Main -- Start
Hello world!
21:48:47.416 [main] DEBUG org.example.Main -- End

あれ？ ConsoleAppenderのみだったときにはなかったDEBUGログが出力されているぞ？？

ここから学びを得ました

✍️appenderのadditivity

Appender Additivity (Chapter 2: Architecture)

The output of a log statement of logger L will go to all the appenders in L and its ancestors.

意訳ロガーLのログステートメントの出力は、Lとその親以上のすべてのappenderに向かいます。

この挙動はオンオフできますが、デフォルトで有効になっています。

Loggers have their additivity flag set to true by default.

リンク先の表が理解の助けになりました。

このadditivityという性質から最初のconfigurationの理解が深まります。

org.exampleロガーにConsoleAppenderを設定
子のorg.example.Mainロガーのappenderはconfigurationにはない
- additivityにより、親のorg.exampleロガーのappenderを使う
- つまり、org.example.MainロガーのINFO以上のログは、親のorg.exampleロガーのConsoleAppenderに流れる

親のロガーのappenderを使っているので、子のロガーにappenderを設定していませんが、出力されたわけですね。

RollingFileAppenderを使った後は以下のようになっているわけです。

org.exampleロガーにConsoleAppenderを設定
子のorg.example.MainロガーにRollingFileAppenderを設定
- 子のロガーは（親のINFO以上と変えて）DEBUG以上をファイルにロギングするように設定
- additivityにより、親のorg.exampleロガーのappenderも使う
- つまり、org.example.MainロガーのDEBUG以上のログは、親のorg.exampleロガーConsoleAppenderに流れる

なので、DEBUGログが標準出力にも出力されたというわけです！

additivityをfalseに設定

logback.xmlを修正しました（該当箇所のみ抜粋）

-    <logger name="org.example.Main" level="DEBUG">
+    <logger name="org.example.Main" level="DEBUG" additivity="false">
        <appender-ref ref="FILE"/>
    </logger>

logFile.logには、DEBUG以上のログが記録されているままです。

#logback.classic pattern: %d %-5level [%thread] %logger{0}: %msg%n
2024-07-09 22:09:28,829 INFO  [main] Main: Start
2024-07-09 22:09:28,830 DEBUG [main] Main: End

標準出力が変わります

Hello world!

additivityを無効にしたので、親のロガーのConsoleAppenderは使いません。
RollingFileAppenderのみです。
なので、標準出力にログが出なくなったわけですね。

Configurationのドキュメントの以下のあたりかと思います（積ん読）
https://logback.qos.ch/manual/configuration.html#overridingCumulativity

終わりに

logbackのappenderのadditivityを知りました。

ロガーには階層構造がある
ログの出力先がappender。ロガーに設定する
子のロガーは自身と親以上に設定されたappenderすべてにログを流す（デフォルトはadditivity="true"）
- この挙動は無効にできる

今回のソースコードは以下にあります。

なお、今回のケースにて子のロガーで（DEBUGを除いて）INFO以上を標準出力にも出したいときには、filterを使うのかなと考えています（宿題事項）

Pythonのロギングと似ている点（ロガーの階層構造）もあれば、appenderのadditivityという違いもあって、興味深かったです

このあたりも面白いと思いました。Effective Level aka Level Inheritance (Chapter 2: Architecture)↩

nikkie-ftnextの日記

イベントレポートや読書メモを発信