かんがるーさんの日記

最近自分が興味をもったものを調べた時の手順等を書いています。今は Spring Boot をいじっています。

Spring Boot 1.4.x の Web アプリを 1.5.x へバージョンアップする ( その14 )( request, response のログを出力する RequestAndResponseLogger クラスを修正する )

概要

記事一覧はこちらです。

Spring Boot 1.4.x の Web アプリを 1.5.x へバージョンアップする ( その13 )( jar ファイルを作成して動作確認する ) の続きです。

  • 今回の手順で確認できるのは以下の内容です。
    • request, response のデータを出力する ksbysample.webapp.lending.aspect.logging.RequestAndResponseLogger を作成していますが、以下2つの問題があることに気づきました。今回はそれを修正します。
      • ログを出力する対象を @RequestMapping アノテーションが付加されたメソッドとしていたのですが、この条件だと Spring Framework 4.3 から追加された @GetMapping, @PostMapping アノテーションが付加されたメソッドではログが出力されないことに気づきました。ログが出力されるよう変更します。
      • @RequestMapping アノテーションが付加されたメソッドで例外が throw されて、応答を返すのが @ExceptionHandler メソッドが付加されたメソッドになった時に response のログが出力されないことに気づきました。こちらもログが出力されるよう変更します。

参照したサイト・書籍

  1. Spring Aspectj @Before all rest method
    http://techqa.info/programming/question/42642681/Spring-Aspectj–Before-all-rest-method

目次

  1. 今回の修正・動作確認のための前準備
    1. 今回の動作確認で使用する SampleController クラスを Spring Security による認証の対象外にする
    2. RequestAndResponseLogger の対象となるパッケージを ksbysample.webapp.lending.webksbysample.webapp.lending へ変更する
  2. @GetMapping, @PostMapping アノテーションが付加されたメソッドでも request, response のログが出力されるようにする
  3. エラーが発生して @ExceptionHandler アノテーションを付加したメソッドが応答を返す時でも response のログが出力されるようにする

手順

今回の修正・動作確認のための前準備

今回の動作確認で使用する SampleController クラスを Spring Security による認証の対象外にする

今回の RequestAndResponseLogger クラスの修正では、動作確認に ksbysample.webapp.lending.SampleController クラスを使用することにします。ただし SampleController クラスに関連付けている URL /sample は Spring Security の認証が必要な状態なので、認証の対象外にします。

src/main/java/ksbysample/webapp/lending/config/WebSecurityConfig.java を以下のように変更します。

@Configuration
@Order(SecurityProperties.ACCESS_OVERRIDE_ORDER)
public class WebSecurityConfig extends WebSecurityConfigurerAdapter {

    ..........

    @Override
    protected void configure(HttpSecurity http) throws Exception {
        http.authorizeRequests()
                // 認証の対象外にしたいURLがある場合には、以下のような記述を追加します
                // 複数URLがある場合はantMatchersメソッドにカンマ区切りで対象URLを複数列挙します
                // .antMatchers("/country/**").permitAll()
                ..........
                .antMatchers("/sample/**").permitAll()
                .anyRequest().authenticated();
        ..........
  • .antMatchers("/sample/**").permitAll() を追加します。

RequestAndResponseLogger の対象となるパッケージを ksbysample.webapp.lending.webksbysample.webapp.lending へ変更する

ksbysample.webapp.lending.SampleController クラスを使用するので、RequestAndResponseLogger の対象となるパッケージを ksbysample.webapp.lending.webksbysample.webapp.lending へ変更します。

src/main/java/ksbysample/webapp/lending/aspect/logging/RequestAndResponseLogger.java を以下のように変更します。

@Aspect
@Component
public class RequestAndResponseLogger {

    ..........

    /**
     * @param pjp ???
     * @return ???
     * @throws Throwable
     */
    @Around(value = "execution(* ksbysample.webapp.lending..*.*(..))"
            + "&& @annotation(org.springframework.web.bind.annotation.RequestMapping)")
    public Object logginRequestAndResponse(ProceedingJoinPoint pjp)
            throws Throwable {
  • execution(* ksbysample.webapp.lending.web..*.*(..))execution(* ksbysample.webapp.lending..*.*(..)) へ変更します。

@GetMapping, @PostMapping アノテーションが付加されたメソッドでも request, response のログが出力されるようにする

例えば ksbysample.webapp.lending.SampleController クラスに @RequestMapping アノテーションを付加したメソッドを追加し、

@Controller
@RequestMapping("/sample")
public class SampleController {

    ..........

    /**
     * {@link RequestMapping}, {@link GetMapping}, {@link PostMapping} アノテーションを付加
     * したメソッドが呼び出された時に {@link RequestAndResponseLogger} クラスで request, response
     * が出力されることを確認するための動作確認用のメソッド
     *
     * @return 画面に出力する文字列
     */
    @RequestMapping("/hello")
    @ResponseBody
    public String hello() {
        return "hello";
    }

}

Tomcat を起動して http://localhost:8080/sample/hello にアクセスすると、RequestAndResponseLogger クラスにより request, response のログが出力されます。

f:id:ksby:20170713002633p:plain

hello メソッドに付加するアノテーションを @GetMapping に変更すると、

    @GetMapping("/hello")
    @ResponseBody
    public String hello() {
        return "hello";
    }

request, response のログが出力されません。

f:id:ksby:20170713003220p:plain

@GetMapping は以下の実装の composed annotation ですが、AspectJ@annotation(org.springframework.web.bind.annotation.RequestMapping) という Pointcut の指定では @GetMapping は対象にならないようです。

f:id:ksby:20170713003759p:plain

単純に対象にしたいアノテーションを || で結合して指定すると request, response のログが出力されるようにはなるのですが、出来れば @RequestMapping アノテーションを使用した composed annotation をシンプルに指定できるようにしたいです。

    @Around(value = "execution(* ksbysample.webapp.lending..*.*(..))"
            + " && (@annotation(org.springframework.web.bind.annotation.RequestMapping)"
            + " || @annotation(org.springframework.web.bind.annotation.GetMapping)"
            + " || @annotation(org.springframework.web.bind.annotation.PostMapping)"
            + " || @annotation(org.springframework.web.bind.annotation.PutMapping)"
            + " || @annotation(org.springframework.web.bind.annotation.DeleteMapping)"
            + " || @annotation(org.springframework.web.bind.annotation.PatchMapping))")
    public Object logginRequestAndResponse(ProceedingJoinPoint pjp)
            throws Throwable {

指定する方法がないか調べてみたところ、Spring Aspectj @Before all rest method という記事を見つけました。execution(@(@org.springframework.web.bind.annotation.RequestMapping *) * *(..)) と指定すれば @RequestMapping アノテーションを使用した composed annotation が付加されたメソッドが全て対象になるようです。

ただしこの条件だけだと @RequestMapping アノテーションが対象に含まれないので、以下のように変更することにします。

@Aspect
@Component
public class RequestAndResponseLogger {

    ..........

    /**
     * {@link RequestMapping} アノテーションが付加されたメソッドを Join Point にする Pointcut
     */
    @Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping)")
    public void requestMappingAnnotation() {
    }

    /**
     * {@link GetMapping}, {@link PostMapping} 等 {@link RequestMapping} アノテーションを使用した
     * composed annotation が付加されたメソッドを Join Point にする Pointcut
     */
    @Pointcut("execution(@(@org.springframework.web.bind.annotation.RequestMapping *) * *(..))")
    public void requestMappingComposedAnnotations() {
    }

    /**
     * @param pjp ???
     * @return ???
     * @throws Throwable
     */
    @Around(value = "execution(* ksbysample.webapp.lending..*.*(..))"
            + " && (requestMappingAnnotation() || requestMappingComposedAnnotations())")
    public Object logginRequestAndResponse(ProceedingJoinPoint pjp)
            throws Throwable {

これで @RequestMapping の時でも request, response のログが出力され、

    @RequestMapping("/hello")
    @ResponseBody
    public String hello() {
        return "hello";
    }

f:id:ksby:20170713011034p:plain

@GetMapping の時でも request, response のログが出力されます。

    @GetMapping("/hello")
    @ResponseBody
    public String hello() {
        return "hello";
    }

f:id:ksby:20170713011351p:plain

エラーが発生して @ExceptionHandler アノテーションを付加したメソッドが応答を返す時でも response のログが出力されるようにする

ksbysample.webapp.lending.SampleController クラスに以下の hello メソッド、handlerException メソッドを追加し、hello メソッドでリクエストを受けて handlerException メソッドでレスポンスが返るようにします。

    @GetMapping("/hello")
    @ResponseBody
    public String hello() {
        if (true) {
            throw new RuntimeException();
        }
        return "hello";
    }

    @ExceptionHandler(RuntimeException.class)
    @ResponseBody
    public String handlerException() {
        return "RuntimeException";
    }

Tomcat を起動して http://localhost:8080/sample/hello にアクセスすると、RequestAndResponseLogger クラスにより request のログは出力されますが、response のログは出力されません。

f:id:ksby:20170713013930p:plain

RequestAndResponseLogger クラスに @ExceptionHandler アノテーションが付加されたメソッドが呼び出された後に response のログを出力するための After Returning Advice のメソッドを追加します。以下のように変更します。

@Aspect
@Component
public class RequestAndResponseLogger {

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

    private static final String POINTCUT_ALL_CLASS_AND_METHOD_UNDER_APPLICATION_PACKAGE
            = "execution(* ksbysample.webapp.lending..*.*(..))";

    ..........

    /**
     * Web アプリケーションの package 配下の全てのクラスのメソッドを Join Point にする Pointcut
     */
    @Pointcut(POINTCUT_ALL_CLASS_AND_METHOD_UNDER_APPLICATION_PACKAGE)
    public void allClassAndMethodUnderApplicationPackage() {
    }

    ..........

    @Around(value = "allClassAndMethodUnderApplicationPackage()"
            + " && (requestMappingAnnotation() || requestMappingComposedAnnotations())")
    public Object logginRequestAndResponse(ProceedingJoinPoint pjp)
            throws Throwable {
        ..........
    }

    @After(value = "allClassAndMethodUnderApplicationPackage()"
            + " && @annotation(org.springframework.web.bind.annotation.ExceptionHandler)")
    public void logginResponseAfterExceptionHandler() {
        HttpServletResponse response
                = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getResponse();
        loggingResponse(response);
    }
  • Web アプリケーションの package 配下の全てのクラスのメソッドを対象にする PointCut 式 execution(* ksbysample.webapp.lending..*.*(..)) を今回追加する After Returning Advice のメソッドでも使用したいので、定数文字列 POINTCUT_ALL_CLASS_AND_METHOD_UNDER_APPLICATION_PACKAGE と allClassAndMethodUnderApplicationPackage メソッドを追加します。
  • logginRequestAndResponse メソッドの @Around アノテーションに指定する Pointcut 式を allClassAndMethodUnderApplicationPackage() に変更します。
  • @ExceptionHandler アノテーションが付加されたメソッドが呼び出された後に処理を行う @After アノテーションが付加された logginResponseAfterExceptionHandler メソッドを追加します。

再度 Tomcat を起動して http://localhost:8080/sample/hello にアクセスすると、今度は reponse のログも出力されました。

f:id:ksby:20170713023614p:plain

最後に src/main/java/ksbysample/webapp/lending/aspect/logging/RequestAndResponseLogger.java のソースを記載します。

ソースコード

RequestAndResponseLogger.java

package ksbysample.webapp.lending.aspect.logging;

import com.google.common.collect.Iterators;
import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.Arrays;
import java.util.Map;
import java.util.stream.StreamSupport;

/**
 * ???
 */
@Aspect
@Component
public class RequestAndResponseLogger {

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

    private static final String POINTCUT_ALL_CLASS_AND_METHOD_UNDER_APPLICATION_PACKAGE
            = "execution(* ksbysample.webapp.lending..*.*(..))";

    private static final String LOG_REQUEST_INFO = "[req][info  ] ";
    private static final String LOG_REQUEST_HEADER = "[req][header] ";
    private static final String LOG_REQUEST_COOKIE = "[req][cookie] ";
    private static final String LOG_REQUEST_PARAMETER = "[req][param ] ";

    private static final String LOG_RESPONSE_INFO = "[res][info  ] ";
    private static final String LOG_RESPONSE_HEADER = "[res][header] ";

    /**
     * Web アプリケーションの package 配下の全てのクラスのメソッドを Join Point にする Pointcut
     */
    @Pointcut(POINTCUT_ALL_CLASS_AND_METHOD_UNDER_APPLICATION_PACKAGE)
    public void allClassAndMethodUnderApplicationPackage() {
    }

    /**
     * {@link RequestMapping} アノテーションが付加されたメソッドを Join Point にする Pointcut
     */
    @Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping)")
    public void requestMappingAnnotation() {
    }

    /**
     * {@link GetMapping}, {@link PostMapping} 等 {@link RequestMapping} アノテーションを使用した
     * composed annotation が付加されたメソッドを Join Point にする Pointcut
     */
    @Pointcut("execution(@(@org.springframework.web.bind.annotation.RequestMapping *) * *(..))")
    public void requestMappingComposedAnnotations() {
    }

    /**
     * @param pjp ???
     * @return ???
     * @throws Throwable
     */
    @Around(value = "allClassAndMethodUnderApplicationPackage()"
            + " && (requestMappingAnnotation() || requestMappingComposedAnnotations())")
    public Object logginRequestAndResponse(ProceedingJoinPoint pjp)
            throws Throwable {
        HttpServletRequest request
                = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        loggingRequest(request);
        Object ret = pjp.proceed();
        HttpServletResponse response
                = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getResponse();
        loggingResponse(response);

        return ret;
    }

    /**
     * ???
     */
    @After(value = "allClassAndMethodUnderApplicationPackage()"
            + " && @annotation(org.springframework.web.bind.annotation.ExceptionHandler)")
    public void logginResponseAfterExceptionHandler() {
        HttpServletResponse response
                = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getResponse();
        loggingResponse(response);
    }

    private void loggingRequest(HttpServletRequest request) {
        loggingRequestInfo(request);
        loggingRequestHeaders(request);
        loggingRequestCookies(request);
        loggingRequestParameters(request);
    }

    private void loggingResponse(HttpServletResponse response) {
        loggingResponseInfo(response);
        loggingResponseHeaders(response);
    }

    private void loggingRequestInfo(HttpServletRequest request) {
        StringBuilder sb = new StringBuilder();
        append(sb, "REQUEST_URI", request.getRequestURI());
        append(sb, ", SERVLET_PATH", request.getServletPath());
        logging(LOG_REQUEST_INFO, null, sb.toString());

        sb = new StringBuilder();
        append(sb, "CHARACTER_ENCODING", request.getCharacterEncoding());
        append(sb, ", CONTENT_LENGTH", String.valueOf(request.getContentLength()));
        append(sb, ", CONTENT_TYPE", request.getContentType());
        append(sb, ", LOCALE", String.valueOf(request.getLocale()));
        append(sb, ", SCHEME", request.getScheme());
        logging(LOG_REQUEST_INFO, null, sb.toString());

        sb = new StringBuilder();
        append(sb, "REMOTE_ADDR", request.getRemoteAddr());
        append(sb, ", REMOTE_HOST", request.getRemoteHost());
        append(sb, ", SERVER_NAME", request.getServerName());
        append(sb, ", SERVER_PORT", String.valueOf(request.getServerPort()));
        logging(LOG_REQUEST_INFO, null, sb.toString());

        sb = new StringBuilder();
        append(sb, "CONTEXT_PATH", request.getContextPath());
        append(sb, ", REQUEST_METHOD", request.getMethod());
        append(sb, ", QUERY_STRING", request.getQueryString());
        append(sb, ", PATH_INFO", request.getPathInfo());
        append(sb, ", REMOTE_USER", request.getRemoteUser());
        logging(LOG_REQUEST_INFO, null, sb.toString());
    }

    private void loggingRequestHeaders(HttpServletRequest request) {
        Iterable<String> headerNameList = () -> Iterators.forEnumeration(request.getHeaderNames());
        StreamSupport.stream(headerNameList.spliterator(), false)
                .filter(headerName -> !StringUtils.equals(headerName, "cookie"))
                .forEach(headerName -> {
                    Iterable<String> headerList = () -> Iterators.forEnumeration(request.getHeaders(headerName));
                    headerList.forEach(header -> logging(LOG_REQUEST_HEADER, headerName, header));
                });
    }

    private void loggingRequestCookies(HttpServletRequest request) {
        if (request.getCookies() != null) {
            Arrays.asList(request.getCookies()).forEach(cookie -> {
                StringBuilder sb = new StringBuilder();
                sb.append("name = ")
                        .append(cookie.getName())
                        .append(", value = ")
                        .append(cookie.getValue())
                        .append(", domain = ")
                        .append(cookie.getDomain())
                        .append(", path = ")
                        .append(cookie.getPath())
                        .append(", maxage = ")
                        .append(cookie.getMaxAge())
                        .append(", secure = ")
                        .append(cookie.getSecure())
                        .append(", httponly = ")
                        .append(cookie.isHttpOnly());
                logging(LOG_REQUEST_COOKIE, null, sb.toString());
            });
        }
    }

    private void loggingRequestParameters(HttpServletRequest request) {
        Map<String, String[]> parameterMap = request.getParameterMap();
        parameterMap.forEach((key, values) -> {
            Arrays.asList(values).forEach(value -> logging(LOG_REQUEST_PARAMETER, key, value));
        });
    }

    private void loggingResponseInfo(HttpServletResponse response) {
        StringBuilder sb = new StringBuilder();
        append(sb, "RESPONSE_STATUS", String.valueOf(response.getStatus()));
        append(sb, ", CHARACTER_ENCODING", response.getCharacterEncoding());
        append(sb, ", CONTENT_TYPE", response.getContentType());
        append(sb, ", LOCALE", String.valueOf(response.getLocale()));
        logging(LOG_RESPONSE_INFO, null, sb.toString());
    }

    private void loggingResponseHeaders(HttpServletResponse response) {
        response.getHeaderNames().forEach(headerName -> {
            response.getHeaders(headerName).forEach(header -> logging(LOG_RESPONSE_HEADER, headerName, header));
        });
    }

    private void logging(String title, String name, String value) {
        StringBuilder sb = new StringBuilder(title);
        if (name != null) {
            sb.append(name);
            sb.append(" = ");
        }
        sb.append(value);
        logger.info(sb.toString());
    }

    private void append(StringBuilder sb, String name, String value) {
        sb.append(name);
        sb.append(" = ");
        sb.append(value);
    }

}

履歴

2017/07/13
初版発行。