SLF4J と Logback でロギング！

前回の『Spring AOP で流れを追う！』で、特定の Aspect(相、特徴) を持つメソッド周りの動きを捕捉したので、今回は取得した情報を基にメッセージを整形し、ログに残します。

SLF4J
SLF4J(Simple Logging Facade for Java) とは、公式サイトにある SLF4J user manual のイラストが表しているように、log4j や Logback といった様々な Logging Framework にシンプルな“Facade(ファサード)”、「外観」を提供するツールです。

因みに、この SLF4J だけでも前回の最後で見せたようなログメッセージをコンソールに出力することができます。

準備 - SLF4J
前回書いたとおり SLF4J サイトから slf4j-[version] の圧縮ファイルを持ってきて解凍後、slf4j-api-[version].jar と slf4j-simple-[version].jar を /WEB-INF/lib にコピーし、ビルドパスにも登録します。

準備 - Logback
SLF4J user manual に『Logback の Logger クラスは SLF4J の Logger インターフェースの直接的な実装クラスなので、両者の接続においてリソースのオーバヘッドが無い』という旨が記されています。確かにイラストにも log4j や Apache Commons Logging(JCL の実装)に見られるようなアダプターが必要ない様子が示されています。

(これを信じて)Logback Project サイトから logback-[version] の圧縮ファイルを持ってきます。解凍先に出てくる 3 つの jar の内、次の 2 を /WEB-INF/ lib にコピーします。

logback-classic-[version].jar
logback-core-[version].jar

今回 Servlet のアクセスログは取らないので logback-access-[version].jar は使いません。


Logback の構成 - logback.xml
The logback manual の“Chapter 3: Logback configuration”によると、Logback は初期化時にまず、以下の順番でクラスパス上の構成ファイルを探します。

1. logback.groovy
2. logback-test.xml
3. logback.xml

クラスパスに以上のファイルが見つからなかった場合は自動的に ch.qos.logback.classic パッケージの BasicConfigurator を呼び出して基本構成を行います。

今回は、以下の“logback.xml”を作成しました。コンソール出力用(STDOUT)とファイル出力用(FILE)の 2 つの appender を定義しています。後者は前者に対して、より詳細な内容となるように定義しています。

logback.xml

<?xml version="1.0" encoding="utf-8"?>
<configuration debug="false">
  <contextName>ishtar</contextName>
  
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%contextName] %-5level %logger{18} - %msg%n</pattern>
    </encoder>
  </appender>
  
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>d:/usr/var/logs/logback/ishtar.log</file>
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%contextName] %-5level [%thread] %logger{36} [%file:%line] %msg%n</pattern>
    </encoder>
  </appender>
  
  <root level="info">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

<appender>要素
2 つの appender にname 属性で「STDOUT」、「FILE」という名前を定義しています。STDOUT では ConsoleAppender クラス、FILE では FileAppender クラスを使用します。両クラスとも OutputStreamAppender クラスを extends したもので、子要素の <encoder> で OutputSteam に乗せるバイトアレイへの変換方法などを Encoder に知らせます。

<pattern>要素
<encoder> の子要素である <pattern> で、具体的なレイアウトを指定します。今回は次の項目を適当に組み合わせて各 appender に設定しています。

時刻：%d{HH:mm:ss.SSS}
コンテキスト名：%contextName
ログレベル：level
スレッド名：%thread
ロガー名：%logger{文字数}
ロガーが出したメッセージ：%msg

指定可能な項目についての詳細はマニュアルの“Chapter 6: Layouts”にあります。

<timestamp>要素
尚、<timestamp>要素を使うと、例えば日付ごとに新しいログファイルを生成させることができます。

<contextName>ishtar</contextName>
  <timestamp key="byDate" datePattern="yyyyMMdd"/>
    ：
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>d:/usr/var/logs/logback/ishtar-${byDate}.log</file>
    ：
  </appender>

マニュアルの“Chapter 4: Appenders”に Appender についての詳細が記されています。ロールオーバーやリモートホスト/SMTPによる転送、データベースへの記録など、試してみたい機能が色々とあります。


メッセージの成型
Logback の導入に伴い前回作成した WebAdvices クラスの各 Advice メソッドに手を加えました。

ポイントは、SLF4J がサポートする“parameterized logging”と呼ばれる機能を利用していることです。直訳すると「パラメーター化されたロギング」となりますが、要は、雛形に含まれるプレースホルダーと文字列を対応付けてメッセージを成型する仕掛けということです。

logger.info()メソッドは、雛形となる String 型の引数と、そこに含まれる各プレースホルダー‘{}’に当てはめる文字列を Object[] 型の引数で受け取ることができます。WebAdvice クラスでは、これを利用して outputLogMessage() という private メソッドへの可変長引数という形でプレースホルダーに適用する値を渡しています。

WebAdvices.java(抜粋)

package com.scopeandtarget.wrider.aop.advice;
  ：
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Aspect
@Component
public class WebAdvices {
  
  private Logger logger = LoggerFactory.getLogger(WebAdvices.class);

  @Before(..)
  public void logFieldValidationOccured(..) {
    
    String format = "{}.{} will be invoked! [{}]";
    outputLogMessage(
        format, 
        jp.getTarget().getClass().getSimpleName(), 
        jp.getSignature().getName(), 
        param.toString());
    
  }
  
  @AfterReturning(..)
  public Object logFieldValidationFinished(..) {
    
    String format = "{}.{} completed! result is {}";
    outputLogMessage(
        format, 
        jp.getTarget().getClass().getSimpleName(), 
        jp.getSignature().getName(), 
        retVal.toString());
    
    return retVal;
  }
  
  @Around(..)
  public Object logFieldValidationOnGoing(..)  throws Throwable {
    
    String format = "{}.{} is on going!";
    outputLogMessage(
        format, 
        pjp.getTarget().getClass().getSimpleName(), 
        pjp.getSignature().getName());
    
    return pjp.proceed();
  }
  
  private void outputLogMessage(String format, String... args) {
    logger.info(format, args);
  }
}

前回は、地道に文字列を連結して System.out.println() していましたが、今回はプレースホルダーを使ったことでコードが見易くなったと思います。


実行！
以上で一通りの作業は完了です。アプリケーションを起動しブラウザーで /account/login.html にアクセスすると、logback.xml で設定したログファイル([contextName].log)が作成され、呼び出されたバリデーターやフォームに入力されたデータ、検証結果、スレッド名、各 Advice メソッドで成型されたメッセージなどが克明に記録されています。

ishtar.log(抜粋)

：
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckEmailValidator.isValid will be invoked! [wrider@abc.com]
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckEmailValidator.isValid is on going!
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckEmailValidator.isValid completed! result is true
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckPasswordValidator.isValid will be invoked! [123456]
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckPasswordValidator.isValid is on going!
14:42:10.156 [ishtar] INFO  [http-bio-8080-exec-7] wrider.aop.advice.WebAdvices [WebAdvices.java:66] CheckPasswordValidator.isValid completed! result is true
  ：

当然の話ですが、アプリケーションは見た目上動いているだけでは駄目で、その内部動作を詳しく把握しておくことが理想です。Spring AOP と Logback のようなロギング・フレームワークを活用すれば、処理フローの捕捉と記録が割りと容易にできます。

ロギング・フレームワークの「機能面」に絞って言えば、開発や評価だけでなく、例えば「ログローテーションをきちんと計画するようなシステム」とか「アクセスログを DB に蓄積して、解析を行うようなシステム」とか、色々な用途に対応できると思います。