はじめに

ログ出力に関するあるあるネタと解決策です。

Logbackでの「ロギング要求の生成元」の出力

Logbackでは、パターンレイアウトに以下の変換指定子を指定することで、「ロギング要求の生成元」の情報をログ出力に含めることができます¹。

変換指定子 (別名)	出力内容
C (class)	呼び出し元のクラス名(FQCN)
M (method)	呼び出し元のメソッド名
F (file)	ソースコードファイル名
L (line)	ソースコードファイル中の行番号
caller²	呼び出し元の位置情報

本記事では、以下の設定をログ出力の例として使用します。
pattern要素の内容に注目してください。この設定により、クラス名やファイル名などをログに出力させることができます。デバッグが捗りますね。

logback.xml

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>[[%class.%method\(%file:%line\)]] %logger{0} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

ログ出力例

[[com.example.demo.DemoLogApplication.main(DemoLogApplication.java:16)]] DemoLogApplication - hello

変換指定子の詳細はマニュアルをご参照ください。

logback マニュアル

【問題】自作Loggerクラスの場合

様々な事情によりSLF4JのLoggerを直接使わずに、自作のLoggerを定義する場合があります。
このとき、単純にSLF4JのLoggerに処理を委譲(いわゆるWrapper)すると、「ロギング要求の生成元」が全て自作Loggerになってしまいます。

MyWrongLogger.java

package com.example.demo;

import org.slf4j.LoggerFactory;
import org.slf4j.Marker;

public class MyWrongLogger {
  // 委譲先となるSLF4JのLogger
  private final org.slf4j.Logger logger;

  // コンストラクタは非公開
  private MyWrongLogger(org.slf4j.Logger logger) {
    this.logger = logger;
  }

  // ファクトリメソッド
  public static final MyWrongLogger getLogger(Class<?> clazz) {
    org.slf4j.Logger logger = LoggerFactory.getLogger(clazz);
    return new MyWrongLogger(logger);
  }

  // 以下、loggerへの委譲

  public boolean isTraceEnabled() {
    return logger.isTraceEnabled();
  }

  public void trace(String msg) {
    logger.trace(msg);
  }

  // (以下略)

}

DemoLogApplication.java

package com.example.demo;

public class DemoLogApplication {
  private static final MyWrongLogger WRONG_LOGGER = MyWrongLogger.getLogger(DemoLogApplication.class);

  public static void main(String[] args) {
    WRONG_LOGGER.info("hello");
    WRONG_LOGGER.info("hello {}", "xxx");
    WRONG_LOGGER.info("exception", new Exception("test"));
    WRONG_LOGGER.info("{} {} {} exception", 1, 2, 3, new Exception("test"));
  }
}

ログ出力例(「ロギング要求の生成元」がMyWrongLoggerになってしまっている)

[[com.example.demo.MyWrongLogger.info(MyWrongLogger.java:122)]] DemoLogApplication - hello
[[com.example.demo.MyWrongLogger.info(MyWrongLogger.java:126)]] DemoLogApplication - hello xxx
[[com.example.demo.MyWrongLogger.info(MyWrongLogger.java:138)]] DemoLogApplication - exception
java.lang.Exception: test
	at com.example.demo.DemoLogApplication.main(DemoLogApplication.java:11)
[[com.example.demo.MyWrongLogger.info(MyWrongLogger.java:134)]] DemoLogApplication - 1 2 3 exception
java.lang.Exception: test
	at com.example.demo.DemoLogApplication.main(DemoLogApplication.java:12)

確かに、実際にloggerのメソッドを呼び出しているのはMyWrongLoggerなのですが……
こんな残念なログ、たまにありますよね。

【解決策】LocationAwareLogger

SLF4JのLocationAwareLogger³を使うことで、この問題を解決できます。
LocationAwareLoggerのlogメソッドでは、FQCNを指定することができます。

org.slf4j.spi.LocationAwareLogger

public void log(Marker marker, String fqcn, int level, String message, Object[] argArray, Throwable t);

LogbackのLogger⁴は、LocationAwareLoggerを実装しています。
つまり、ログ出力の実装にLogbackを使用している場合、LoggerFactoryから取得したLogger⁵をLocationAwareLoggerにキャストすることができます。

以下がLocationAwareLoggerの使用例です。

MyLocationAwareLogger.java

package com.example.demo;

import static org.slf4j.spi.LocationAwareLogger.*;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;

public class MyLocationAwareLogger {
  // Marker(今回は使用しない)
  private static final Marker MARKER = null;
  // このクラスのFQCN 
  private static final String FQCN = MyLocationAwareLogger.class.getName();

  // 委譲先となるSLF4JのLocationAwareLogger
  private final org.slf4j.spi.LocationAwareLogger logger;

  // コンストラクタは非公開
  private MyLocationAwareLogger(org.slf4j.spi.LocationAwareLogger logger) {
    this.logger = logger;
  }

  // ファクトリメソッド
  public static MyLocationAwareLogger getLogger(Class<?> clazz) {
    org.slf4j.spi.LocationAwareLogger logger = (org.slf4j.spi.LocationAwareLogger) LoggerFactory.getLogger(clazz);
    return new MyLocationAwareLogger(logger);
  }

  //<<< isXxxEnabled >>>
  public boolean isTraceEnabled() { return logger.isTraceEnabled(); }
  public boolean isDebugEnabled() { return logger.isDebugEnabled(); }
  public boolean isInfoEnabled () { return logger.isInfoEnabled (); }
  public boolean isWarnEnabled () { return logger.isWarnEnabled (); }
  public boolean isErrorEnabled() { return logger.isErrorEnabled(); }
  //---

  //<<< log >>>
  // (String msg)
  public void trace(String msg)                         { logger.log(MARKER, FQCN, TRACE_INT, msg,    null,      null); }
  public void debug(String msg)                         { logger.log(MARKER, FQCN, DEBUG_INT, msg,    null,      null); }
  public void info (String msg)                         { logger.log(MARKER, FQCN, INFO_INT,  msg,    null,      null); }
  public void warn (String msg)                         { logger.log(MARKER, FQCN, WARN_INT,  msg,    null,      null); }
  public void error(String msg)                         { logger.log(MARKER, FQCN, ERROR_INT, msg,    null,      null); }
  // (String msg, Throwable t)
  public void trace(String msg,    Throwable t)         { logger.log(MARKER, FQCN, TRACE_INT, msg,    null,      t   ); }
  public void debug(String msg,    Throwable t)         { logger.log(MARKER, FQCN, DEBUG_INT, msg,    null,      t   ); }
  public void info (String msg,    Throwable t)         { logger.log(MARKER, FQCN, INFO_INT,  msg,    null,      t   ); }
  public void warn (String msg,    Throwable t)         { logger.log(MARKER, FQCN, WARN_INT,  msg,    null,      t   ); }
  public void error(String msg,    Throwable t)         { logger.log(MARKER, FQCN, ERROR_INT, msg,    null,      t   ); }
  // (String format, Object... arguments)
  public void trace(String format, Object... arguments) { logger.log(MARKER, FQCN, TRACE_INT, format, arguments, null); }
  public void debug(String format, Object... arguments) { logger.log(MARKER, FQCN, DEBUG_INT, format, arguments, null); }
  public void info (String format, Object... arguments) { logger.log(MARKER, FQCN, INFO_INT,  format, arguments, null); }
  public void warn (String format, Object... arguments) { logger.log(MARKER, FQCN, WARN_INT,  format, arguments, null); }
  public void error(String format, Object... arguments) { logger.log(MARKER, FQCN, ERROR_INT, format, arguments, null); }
  //---
}

DemoLogApplication.java

package com.example.demo;

public class DemoLogApplication {
  private static final MyLocationAwareLogger MY_LOGGER = MyLocationAwareLogger.getLogger(DemoLogApplication.class);

  public static void main(String[] args) {
    MY_LOGGER.info("hello");
    MY_LOGGER.info("hello {}", "xxx");
    MY_LOGGER.info("exception", new Exception("test"));
    MY_LOGGER.info("{} {} {} exception", 1, 2, 3, new Exception("test"));
  }
}

ログ出力例(正しい「ロギング要求の生成元」が出力されている)

[[com.example.demo.DemoLogApplication.main(DemoLogApplication.java:16)]] DemoLogApplication - hello
[[com.example.demo.DemoLogApplication.main(DemoLogApplication.java:17)]] DemoLogApplication - hello xxx
[[com.example.demo.DemoLogApplication.main(DemoLogApplication.java:18)]] DemoLogApplication - exception
java.lang.Exception: test
	at com.example.demo.DemoLogApplication.main(DemoLogApplication.java:18)
[[com.example.demo.DemoLogApplication.main(DemoLogApplication.java:19)]] DemoLogApplication - 1 2 3 exception
java.lang.Exception: test
	at com.example.demo.DemoLogApplication.main(DemoLogApplication.java:19)

おわりに

SLF4JのLoggerのメソッドを模倣するだけならば自作のLoggerは不要だと思います。
自作のLoggerを作るなら、ログ出力目的(監査ログや性能ログなど)別にメソッドを用意するなど、有意義なLoggerを作りましょう。
(本記事ではサンプルとして分かりやすくするために、あえてLoggerのメソッドを模倣しました。ご容赦ください)

「ロギング要求の生成元」の取得は高コストな処理のため、実行速度を悪化させます。開発環境などに限定して使用するようにしましょう ↩
出力内容が特殊なため、本記事では取り扱いません ↩
org.slf4j.spi.LocationAwareLogger ↩
ch.qos.logback.classic.Logger ↩
org.slf4j.Logger ↩