EclipseLinkのログ出力でギブアップしたこと…

なんか初めて諦めてしまったことな気がします…(-_-;

EclipseLinkのログ出力でやりたかったこと

去年のエントリ「EclipseLinkのログをSLF4J&Logbackにて出力したい」で、JPQLのクエリからEclipseLinkで生成された実クエリをログ出力できることを確認しました。

これ以降の作業を棚上げしていたのですが、実際にやりたいこととしては以下のようなログ出力を出力することでした。

…
2013-01-29 17:11:29.296,INFO,search,kikutaro777,**画面のID**,10.xx.xx.xx,商談検索を実行
2013-01-29 17:11:30.174,DEBUG,logic,kikutaro777,**画面のID**,10.xx.xx.xx,実行検索クエリ -> 'SELECT t0.OPPORTUNITYNAME, ...
bind => [kikutaro777] '
…

画面ログと内部ロジックのログは分けるとか、そういうレベルの議論もありますが…。

ログ自体はSLF4JとLogbackの組合せで使っていて、EclipseLinkでそのログに上記のようなフォーマットで出したいというものです。

ASP.NETだと多分簡単に上記のようなログを出せるのですが、Java EEだとちょっと悩んでしまったり…。

結論から書くと、ちょっと時間的にもギブアップをして(一応、色々調べてみたのですが…)、クエリ部分は以下のようなログとなりそうです。

…
2013-01-29 17:11:29.296,INFO,search,kikutaro777,**画面のID**,10.xx.xx.xx,商談検索を実行
2013-01-29 17:11:30.174,DEBUG,,,,,実行検索クエリ -> 'SELECT t0.OPPORTUNITYNAME, ...
bind => [kikutaro777] '
…

要はビューサイド、Beanサイドから得る情報は出さない、というノリ…。
まあ、クエリまでログ出すのは、基本的に障害分析とか性能分析のためなので…。

なんだか自分のコーディング力がない気がプンプンしますが、とりあえず、やってみたことだけまとめます。

イメージ

すさまじくざっくりしたショボンな絵ですが…自分はこんな感じでJava EE6内部のイメージをしています。

f:id:kikutaro777:20130129194531p:plain

例えば「商談情報を検索する」みたいなもので、画面で検索ボタン押して、その画面のBackingBeanがEJBのDB検索処理ロジックを呼び出して…みたいな。EJBはステートレスセッションなのでプール上にインスタンスがいて…みたいな。

試した実装

SLF4J経由のLogbackでロギングしてますが、Logbackは以下のような感じで設定しています。

logback.xml

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>/CpqPrototypeLog/logFile.log</File>
        
    <!-- logファイルを区切る設定 -->
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        ...
    </rollingPolicy>
        
    <!-- 出力内容設定 -->
    <encoder>
        <charset>UTF-8</charset>
        <!-- 日付,出力レベル,処理区分,ログイン者ID,画面ID,クライアントIP,内容 -->
        <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS},%-5level,%marker,%X{LOGIN_USER_ID},%X{SCREEN_ID},%X{CLIENT_IP_ADDR},%msg %n</Pattern>
    </encoder>
</appender>

で、EclipseLinkのドキュメントを色々みていくと、CustomLoggerを使って出すのが良い…のかなと(^^;

EclipseLinkのCustomLoggerドキュメント

上記ドキュメントを参考に色々試していたのですが、頭がこんがらがったのでクラス図書きました。

f:id:kikutaro777:20130129194925p:plain

Custom Logger

ほぼサンプルイコールですが、以下のような感じで。Logクラスは内部でSLF4Jでロギングする処理を持つクラスです。
本当はここで、ログイン者情報とか画面IDとかをBackingBeanから取る、あるいはその逆などをしたいのですが、なんともかんとも。

package jp.co.hoge.hogehoge.log;

import org.eclipse.persistence.logging.AbstractSessionLog;
import org.eclipse.persistence.logging.SessionLog;
import org.eclipse.persistence.logging.SessionLogEntry;

public class CustomSessionLog extends AbstractSessionLog implements SessionLog{
    
    //private static Logger logger = LoggerFactory.getLogger("jp.co.hoge.hogehoge.log.CustomSessionLog");
    
    @Override
    public void log(SessionLogEntry sle) {
        Log.info("ログメッセージ:" + sle.getMessage());
    }
}

SessionCustomizerとかSessionEventAdapterとか

SessionCustomizerが入ると以下のような形になるっぽいです。
f:id:kikutaro777:20130129195030p:plain
Adapterとかも触ってみて、なんかできないかなと模索したり。。。

package jp.co.hoge.hogehoge.log;

import org.eclipse.persistence.config.SessionCustomizer;
import org.eclipse.persistence.logging.SessionLog;
import org.eclipse.persistence.sessions.Session;

public class CustomSessionCustomizer implements SessionCustomizer{

    @Override
    public void customize(Session sn) throws Exception {
        SessionLog customLogger = new CustomSessionLog();
        sn.setSessionLog(customLogger);

        sn.getEventManager().addListener(new LogSessionEventAdapter());
    }
}

package jp.co.hoge.hogehoge.log;

import org.eclipse.persistence.sessions.Session;
import org.eclipse.persistence.sessions.SessionEvent;
import org.eclipse.persistence.sessions.SessionEventAdapter;

public class LogSessionEventAdapter extends SessionEventAdapter{
    
    @Override
    public void preExecuteQuery(SessionEvent event) {
        System.out.println("クエリ実行の前に走るイベントです");
    }
}

なんというか、何をしてもBackingBeanと縁が遠すぎてどうしたものかと。
たとえばASP.NETだと、上図のような境界が明確にはないため、なんでもかんでもできるのですが、Java EEって境界がしっかり分かれていて、CDIで注入は簡単ですが、上記のような既存ログの仕組みにどうやってログイン者情報のインスタンスとか伝播(あるいは逆から取得)させていくんだろ…とか悩んでしまったり。