Spring AOPでメソッドのinとoutをlogに出力する

はじめに

Webアプリケーションの開発と保守を行う場合、リクエストとレスポンスの詳細が
logに適切に出力されていると、もしものときの調査・対応に非常に助かることが多いと思います。
今回はAOPを利用して、メソッドのin(引数等)とout(戻り値)を出力させたいと思います。

検証には以前、コチラのシリーズで作成したリポジトリを使用します。

pom.xmlにDependencyを追加

AOPを使用するにあたって、spring-boot-starter-aopを追加します。

pom.xml

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>

LoggingAdviceを追加

実際にaopを使用してメソッドのin-outをlogに出力する処理を追加します。

aspect/LoggingAdvice.java

package com.mijinco0612.springauth0.aspect;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import java.util.ArrayList;

@Aspect
@Component
public class LoggingAdvice {
    private final Logger logger;

    public LoggingAdvice() {
        this.logger = LoggerFactory.getLogger(getClass());
    }

  @Before("execution(* com.mijinco0612.springauth0.controller.api.*.*.*(..))")
  public void invokeApiControllerBefore(JoinPoint joinPoint) {
        outputLog(joinPoint);
    }


    @AfterReturning(pointcut = "execution(* com.mijinco0612.springauth0.controller.api.*.*.*(..))", returning = "returnValue")
    public void invokeControllerAfter(JoinPoint joinPoint, Object returnValue) {
        outputLog(joinPoint, returnValue);
    }

    @AfterThrowing(value = "execution(* com.mijinco0612.springauth0.controller.api.*.*.*(..))", throwing = "e")
    public void invokeControllerAfterThrowing(JoinPoint joinPoint, Throwable e) {
        outputErrorLog(joinPoint, e);
    }


    private void outputLog(JoinPoint joinPoint) {
        String logMessage = "[" + getSessionId() + "]:" + getClassName(joinPoint) + "." + getSignatureName(joinPoint) + ":START:" + getArguments(joinPoint);
        logger.info(logMessage);
    }

    private void outputLog(JoinPoint joinPoint, Object returnValue) {
        String logMessage = "[" + getSessionId() + "]:" + getClassName(joinPoint) + "." + getSignatureName(joinPoint) + ":END:" + getReturnValue(returnValue);
        logger.info(logMessage);
    }

    private void outputErrorLog(JoinPoint joinPoint, Throwable e) {
        String logMessage = "[" + getSessionId() + "]:" + getClassName(joinPoint) + "." + getSignatureName(joinPoint) + ":arguments:" + getArguments(joinPoint);
        logger.error(logMessage, e);
    }

    private String getSessionId() {
        return ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest().getSession().getId();
    }

    private String getClassName(JoinPoint joinPoint) {
        return joinPoint.getTarget().getClass().toString();
    }

    private String getSignatureName(JoinPoint joinPoint) {
        return joinPoint.getSignature().getName();
    }

    private String getArguments(JoinPoint joinPoint) {
        if (joinPoint.getArgs() == null) {
            return "argument is null";
        }

        Object[] arguments = joinPoint.getArgs();
        ArrayList<String> argumentStrings = new ArrayList();

        for (Object argument : arguments) {
            if (argument != null) {
                argumentStrings.add(argument.toString());
            }
        }
        return String.join(",", argumentStrings);
    }

    private String getReturnValue(Object returnValue) {
        return (returnValue != null) ? returnValue.toString() : "return value is null";
    }

}

実際に検証してみる

Posｔmanを使用して以下のようなリクエストを送信してみました

http://localhost:28080/api/v1/echo?echoMessage=testEchoMessage


リクエスト先のコントローラーはこんな感じにしています。

DemoController.java

    @ResponseBody
    @GetMapping("/api/v1/echo")
    public String echoApi(@RequestParam("echoMessage") String message) {
        return "pong"+message;
    }

testEchoMessageという文字列をechoMessageというクエリパラメータに設定してhttp://localhost:28080/api/v1/echoへリクエストしました。

logにはtestEchoMessageという引数とpongtestEchoMessageという戻り値が出力されているはずです。

実際にログをして確認してみましょう。

spring-auth0.log

2018-07-11 13:23:05 |http-nio-28080-exec-10| [INFO] com.mijinco0612.springauth0.aspect.LoggingAdvice [CD896FA8A5798E84FBF0CDBDDE90E7FF]:class com.mijinco0612.springauth0.controller.api.v1.DemoController.echoApi:STARTtestEchoMessage
2018-07-11 13:23:05 |http-nio-28080-exec-10| [INFO] com.mijinco0612.springauth0.aspect.LoggingAdvice [CD896FA8A5798E84FBF0CDBDDE90E7FF]:class com.mijinco0612.springauth0.controller.api.v1.DemoController.echoApi:END:pongtestEchoMessage

出力されました！