Controllerの呼び出し前後にログ出力する方法

はじめに

SpringBootのControllerの呼び出し前後で引数や処理時間をログに出力したく、
調べたところAOPで実現できたので、まとめておく。

基本となる書き方

@Aspect
@Component
public class [任意のクラス名] {

    @Around("execution(public * xxx.yyy.zzz.controller.*.*(..))")
    public Object [任意のメソッド名](final ProceedingJoinPoint pjp) throws Throwable {

            // 前処理

            Object result = pjp.proceed();

            // 後処理

            return result;
        }
    }
}

@Aroundについて

Advice(アドバイス)の1つ。処理時間を計算するために採用した。
他に@Beforeや@After、@AfterReturning、@AfterThrowingがある。

@Aroundの引数について

ポイントカット指示子のこと。
上記コードでは、xxx.yyy.zzz.controllerパッケージの任意のクラス名、(publicな)メソッド名、引数に対して実行する。

クラス名の取得

ProceedingJoinPointから取得できる

pjp.getSignature().getDeclaringTypeName()
    -> "xxx.yyy.zzz.controller.[クラス名]" が返ってくる

メソッド名の取得

ProceedingJoinPointから取得できる

pjp.getSignature().getName()
    -> "[メソッド名]"が返ってくる

引数の取得

ProceedingJoinPointから取得できる

// 引数名
String[] methodArgNames = ((CodeSignature) pjp.getSignature()).getParameterNames();
// 引数の値
Object[] methodArgValues = pjp.getArgs();

コードの全文

@Aspect
@Component
public class ControllerLogger {

    private static final Logger logger = LoggerFactory.getLogger(ControllerLogger.class);

    @Around("execution(public * xxx.yyy.zzz.controller.*.*(..))")
    public Object logging(final ProceedingJoinPoint pjp) throws Throwable {
        // ごちゃごちゃするのでtry-with-resourcesを使用しているが、どうしても例外処理っぽく見える
        try (var scope = new Scope(pjp)) {
            return pjp.proceed();
        }
    }

    private static class Scope implements AutoCloseable {

        private final String declaringTypeName;
        private final String name;
        private final String[] methodArgNames;
        private final Object[] methodArgValues;
        private final long startMs;

        private Scope(final ProceedingJoinPoint pjp) {
            declaringTypeName = pjp.getSignature().getDeclaringTypeName();
            name = pjp.getSignature().getName();
            methodArgNames = ((CodeSignature) pjp.getSignature()).getParameterNames();
            methodArgValues = pjp.getArgs();
            startMs = System.currentTimeMillis();
            logger.info("Controller start : " + declaringTypeName + "#" + name + " " + buildArgs());
        }

        @Override
        public void close() {
            final var endMs = System.currentTimeMillis();
            logger.info("Controller end   : " + declaringTypeName + "#" + name + " " + buildArgs() + " in " + (endMs - startMs) + " ms");
        }

        private String buildArgs() {
            final var result = new StringBuilder();
            result.append("[");
            for (int i = 0; i < methodArgNames.length; i++) {
                if (i != 0) {
                    result.append(", ");
                }
                result.append(methodArgNames[i] + "=" + String.valueOf(methodArgValues[i]));
            }
            result.append("]");
            return result.toString();
        }
    }
}

参考にした記事