ラベル Logback の投稿を表示しています。 すべての投稿を表示
ラベル Logback の投稿を表示しています。 すべての投稿を表示

2012年4月13日金曜日

CGLIB Proxy で捕捉エリアを拡大


Spring Framework リファレンスの“8.6 Proxying mechanisms”に、Spring AOP はターゲットオブジェクトがインターフェースを実装している時は JDK の Dynamic Proxy、インターフェースを実装していない時は CGLIB Proxy を使うと記されています。

今回は、CGLIB Proxy を有効にして Pointcut の対象を広げます。

準備 - cglib
Spring AOP で流れを追う!』で触れたとおり、cglib(Code Generation Library) サイトから cglib-2.2.2.jar をダウンロードし、/WEB-INF/lib にコピーします。

asm
CGLIB Proxy を利用するためにはこれも必要です。cglib サイトのトップページ、あるいはOW2 Consortium サイトの ASM ページに行き、リンクを辿って asm-3.3.1-bin.zip を持ってきたら、解凍先の lib フォルダーに入っている asm-3.3.1.jar を /WEB-INF/lib にコピーします。

最新の asm-4.0 で試したところ cglib-2.2.2 がうまく動きませんでした。


CGLIB Proxy の有効化
リファレンス“8.6 Proxying mechanisms”に従って[servlet-name]-servlet.xml で以下の設定を行います。

<aop:aspectj-autoproxy proxy-target-class="true"/>


Pointcut の追加
まずは Join Point にしたいメソッド周りの特徴を見極めます。以下は『Bean Validation』で手を加えた AccountController クラスの一部です。

AccountController.java(抜粋)
package wrider.controller;
  :

@Controller
@SessionAttributes({"idCard", "userProfile"})
public class AccountController {
  :
  @RequestMapping(value="/account/login.html", method=RequestMethod.POST)
  public ModelAndView login(@Valid IdCard idCard, BindingResult br) {
  :
  }
  :
  @RequestMapping(value="/account/register.html", method=RequestMethod.POST)
  public ModelAndView register(@Valid UserProfile userProfile, BindingResult br) {
  :
  }
  :
}

クラス定義を見ると AccountController は wrider パッケージにあり、インターフェースを implements していないことがわかります。POST リクエストで呼び出される login()メソッドと register()メソッドは public で、どちらも2つ目の引数として BindingResult 型を受け取っています。この辺の特徴を Pointcut に定義したのが以下のコードです。

WebPointcuts.java(抜粋)
@Aspect
@Component
public class WebPointcuts {
  
  @Pointcut("within(com.scopeandtarget.wrider..*)")
  public void inWriderPackage() {}
  :
  @Pointcut("inWriderPackage() && execution(public * *(*,org.springframework..BindingResult))")
  public void postAction() {}
  
}

これは『Spring AOP で流れを追う!』で作った WebPointcuts クラスに手を加え、新たに postAction というメソッドを追加しています。@Pointcut アノテーションの中身を見ると、「wrider パッケージにある全ての型に定義されたメソッド」を表す inWriderPackage と、「public で2つ目の引数に BindingResult 型を持つメソッド」という条件を "&&" でつないでいます。

Advice の追加
続いて、Pointcut に新しく追加した postAction で呼び出される Advice を追加します。

WebAdvices.java(抜粋)
@Before("com.scopeandtarget.wrider.aop.pointcut.WebPointcuts.postAction() && args(*,param)")
  public void logPrePostRequest(final JoinPoint jp, final Object param) {
    
    BindingResult bindingResult = (BindingResult)param;
    
    String format = "{}.{} will be invoked!";
    outputLogMessage(
        format, 
        jp.getTarget().getClass().getSimpleName(), 
        jp.getSignature().getName());
    
    StringBuffer sb = new StringBuffer();
    
    sb.append("BindingResult has ..");
    sb.append(CoreConstants.LINE_SEPARATOR);
    for (Map.Entry entry : bindingResult.getModel().entrySet()) {
      sb.append(" key: " + entry.getKey());
      sb.append(CoreConstants.LINE_SEPARATOR);
      sb.append(" value: " + entry.getValue().toString());
      sb.append(CoreConstants.LINE_SEPARATOR);
      sb.append(" -----------------------------------");
      sb.append(CoreConstants.LINE_SEPARATOR);
    }
    
    logger.info(sb.toString());
  }

新たに logPrePostRequest メソッドが加わりました。@Before アノテーションを付けているので Before Advice です。インターセプトしたメソッドの 2 番目の引数を final Object 型で受け取り、メソッドの中で BindingResult 型にキャストしています。クラス名とメソッド名は、他の Advice と同じように、引数として受け取った JoinPoint を介して取得後、logger.info() でメッセージ内のプレースホルダーに埋め込んで出力しています。

一方 BindingResult は、取り出した key と value を StringBuffer に append しながらループし、最後に logger.info() で出力するようにしています。尚、改行に ch.qos.logback.core.CoreConstants を使用しているため、/WEB-INF/lib の logback-core-[version].jar をビルドパスに登録しています。


実行!
以上で作業は完了です。実際に動かし、吐き出されたログの一部が以下です。まず、CheckPasswordValidator、続いて CheckEmailValidator の isValid で入力値が検証され、AccountController の login メソッドが呼び出されている様子がわかります。検証結果は全て正常なので、最後にある BindingResult の内容は“0 errors”のみです。

尚、検証エラーがあった際の BindingResult の内容は『Validator と MessageSource』に一例を示しています。

ishtar.log
21:47:04.593 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckPasswordValidator.isValid will be invoked! [q1w2e3r4]
21:47:04.593 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckPasswordValidator.isValid is on going!
21:47:04.593 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckPasswordValidator.isValid completed! result is true
21:47:04.640 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckEmailValidator.isValid will be invoked! [wrider@abc.com]
21:47:04.640 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckEmailValidator.isValid is on going!
21:47:04.640 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] CheckEmailValidator.isValid completed! result is true
21:47:04.640 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:93] AccountController.login will be invoked!
21:47:04.640 [ishtar] INFO  [http-bio-8080-exec-3] wrider.aop.advice.WebAdvices [WebAdvices.java:89] BindingResult has ..
 key: idCard
 value: wrider.model.IdCard@1875a82
 -----------------------------------
 key: org.springframework.validation.BindingResult.idCard
 value: org.springframework.validation.BeanPropertyBindingResult: 0 errors
 -----------------------------------


ログと聞くと一見地味な印象ですが、特にセキュリティやマーケティングでは必要不可欠な要素です。CGLIB Proxy を使うことで Pointcut に設定できる Join Point ―― Spring AOP の場合はメソッド実行のタイミングということですが――の領域を広げることができ、それに伴いログデータを採取できる機会も増えます。BigData の重要性が増しているといわれていますが、例えばシステム上でのユーザーの行動についての、より詳細で豊富なデータを集めたいというようなとき、Spring AOP を試してみるのも悪くないと思いました。

2012年4月11日水曜日

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].jarslf4j-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 に蓄積して、解析を行うようなシステム」とか、色々な用途に対応できると思います。