はじめに
メソッドの開始と終了のログ情報は、そこまで処理が到達しているのか、そのメソッドでどの位時間が掛かっているのか、など調査する上で非常に重要なポイントとなる。
コーディングルールとしてメソッドの開始・終了時にログを仕込むように決めていたとしても、仕込んでいないメソッドが必ず現れてくる。
そこでSpringAOPを利用して自動的にロギングする仕組みを構築する。
SpringFrameworkが介在するメソッドの呼び出しには適用されるが、privateメソッドなど独自に呼び出すメソッドには適用されないことに注意してほしい。
大まかな手順
- pom.xmlにAOPを追加する
- ロギング用のアスペクトオブジェクトを作成する
- アプリケーションオブジェクトに
@EnableAspectJAutoProxyアノテーションを追加する
1. pom.xmlにAOPを追加する
他の依存関係に含まれている場合は追加しなくても動作するが、明示的に記載しておいた方が何を使っているか分かるため良いと思う。
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
2.ロギング用のアスペクトオブジェクトを作成する
@Aspect
@Component
public class LoggingAspect {
/** メソッド実行前ロギング */
@Before("execution(* jp.xxxx.xxxx..*(..))")
public void logBeforeMethod(JoinPoint joinPoint) {
String className = joinPoint.getTarget().getClass().getName();
String methodName = joinPoint.getSignature().getName();
Object[] args = joinPoint.getArgs(); // 引数を取得
Logger targetLogger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
targetLogger.debug(className + "." + methodName + " -START- Args:" + Arrays.toString(args));
}
/** メソッド実行後ロギング （正常終了時）*/
@AfterReturning(pointcut = "execution(* jp.xxxx.xxxx..*(..))", returning = "result")
public void logAfterMethod(JoinPoint joinPoint, Object result) {
String className = joinPoint.getTarget().getClass().getName();
String methodName = joinPoint.getSignature().getName();
Logger targetLogger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
targetLogger.debug(className + "." + methodName + " -END- Result:" + result);
}
/** メソッド実行後ロギング（エラー） */
@AfterThrowing(pointcut = "execution(* jp.xxxx.xxxx..*(..))", throwing = "error")
public void logAfterThrowingMethod(JoinPoint joinPoint, Throwable error) {
String className = joinPoint.getTarget().getClass().getName();
String methodName = joinPoint.getSignature().getName();
Logger targetLogger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
targetLogger.error(className + "." + methodName + " -ERROR-", error);
}
}
いくつかポイントを押さえて行こう。
@Aspect アノテーション
AOPで使用するための定義
ポイントカット（pointcut）
メソッドの実行やフィールドアクセスなど、特定のポイントを指定するための式。
この例では実行されたpackage配下のクラスを指定している。
アドバイス（Advice）
どのタイミングで動作するかを指定するアノテーション
- @Before：メソッド実行前に実行
- @After：メソッド実行後に実行
- @AfterReturning：メソッド正常終了後に実行
- @AfterThrowing：メソッド例外スロー後に実行
- @Around：メソッド実行の前後に実行
例では、メソッド実行時の引数、正常終了時のreturn値、エラー時のthrow値をログに出力している。
これにより欲しい情報の記載漏れなどがなくなる。
以下にも注目して貰いたい
Logger targetLogger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
この処理を行うことにより、ログに出力されるクラスがメソッドを実行しているクラスになる。
これを行わず、LoggingAspectクラスのプライベート変数として以下のように定義してしまうと、ログに出力されるクラスがLoggingAspect.classになってしまう。
private static Logger targetLogger = LoggerFactory.getLogger(LoggingAspect.class);
3. アプリケーションオブジェクトに@EnableAspectJAutoProxyアノテーションを追加する
SpringBootの実行アプリケーションに@EnableAspectJAutoProxyアノテーションを追加する
@EnableAspectJAutoProxy
public class ExecApplication {
public static void main(String[] args) {
SpringApplication.run(ExecApplication.class, args);
}
}