ソースコードを見ると非推奨のものを利用しているようなので、その辺もキャッチアップしながら勉強していきます。

コントローラーの処理前と処理後に、ログの出力を行います。

■ロギングについてhttp://terasolunaorg.github.io/guideline/current/ja/ArchitectureInDetail/GeneralFuncDetail/Logging.html

基本的には通常のコンソールログなどの情報では手動で保存などが必要になるが、ロギングライブラリを導入することで作業の時間、証跡、解析など効率的にできる。

参考書籍ではコントローラーの処理前後にこのロギングを挟んでいます。しかし実装方法がHandlerInterceptorAdapterを継承するという古い方法なので、HandlerInterceptorを実装する方法で実装します。

参考：https://aki-bunkei.com/handlerinterceptor/

ロギングにlombokのslf4jを利用します。

インターセプタ

HandlerInterceptorを実装したクラスを作成します。このインターフェースは３つのデフォルトメソッドを持っていますが、今回はコントローラーの処理前後に発火するメソッドをオーバーライドします。

package com.volkruss.misaka.aop;

import lombok.extern.slf4j.Slf4j;
import org.springframework.lang.Nullable;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

/**
 * 設定ファイル
 * com.volkruss.misaka.config.WebMvcConfig
 */
@Component
@Slf4j
public class RequestTracking implements HandlerInterceptor {

    //コントローラーの動作前
    @Override
    public boolean preHandle (HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

        log.info("処理開始");
        return true;
    }

    //コントローラーの操作後
    @Override
    public void postHandle (HttpServletRequest request, HttpServletResponse response, Object handler,
                            @Nullable ModelAndView modelAndView) throws Exception {
        log.info("処理終了");

    }
}

上記のファイルが、どのURLで発動するのかを定義した設定クラスを作成します。WebMvcConfigurerを実装してaddInterceptorsメソッドをオーバーライドします。

@Component
public class WebMvcConfig implements WebMvcConfigurer {
    @Autowired
    private RequestTracking requestTracking;

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(requestTracking)
                .addPathPatterns("/")
                .addPathPatterns("/track");
    }
}

実行して設定クラスで設定したURLにアクセスすると、以下のようにログが流れます。

2022-02-22 00:14:31.434  INFO 20020 --- [nio-8080-exec-2] com.volkruss.misaka.aop.RequestTracking  : 処理開始

2022-02-22 00:14:31.434  INFO 20020 --- [nio-8080-exec-2] com.volkruss.misaka.aop.RequestTracking  : 処理終了

2022-02-22 00:44:41.418  INFO 20020 --- [nio-8080-exec-5] com.volkruss.misaka.aop.RequestTracking  : 処理開始

2022-02-22 00:44:41.471  INFO 20020 --- [nio-8080-exec-5] com.volkruss.misaka.aop.RequestTracking  : 処理終了

引数のhandlerは以下のように説明されています

コントローラーを作成して

@RestController
public class ShopController {
    @GetMapping("/")
    public String home(){
        return "HOME";
    }

    @GetMapping("/track")
    public String track(){
        return "TRACK";
    }
}

デバッグするとコントローラークラスががわかります。

ここのHandlerMethodのbeanを取得すればコントローラーが取得できます

/**
	 * Variant of {@link #HandlerMethod(Object, Method)} that
	 * also accepts a {@link MessageSource} for use from sub-classes.
	 * @since 5.3.10
	 */
	protected HandlerMethod(Object bean, Method method, @Nullable MessageSource messageSource) {
		Assert.notNull(bean, "Bean is required");
		Assert.notNull(method, "Method is required");
		this.bean = bean;
		this.beanFactory = null;
		this.messageSource = messageSource;
		this.beanType = ClassUtils.getUserClass(bean);
		this.method = method;
		this.bridgedMethod = BridgeMethodResolver.findBridgedMethod(method);
		ReflectionUtils.makeAccessible(this.bridgedMethod);
		this.parameters = initMethodParameters();
		evaluateResponseStatus();
		this.description = initDescription(this.beanType, this.method);
	}
....
	/**
	 * Return the bean for this handler method.
	 */
	public Object getBean() {
		return this.bean;
	}

参考書では、ここのgetBeanメソッドでHandlerMethodからコントローラーが実装したFunctionNameAwareインターフェースを取得して、getFunctionNameメソッドを呼び出します。

今回はdescriptionを取得してログに出力したいと思います。descriptionはtoStroingメソッドを呼出せば取得できます

@Override
	public String toString() {
		return this.description;
	}

descriptionの取得

参考書籍のソースではあらゆるコントローラークラスが機能名を取得できるようになっています。これは、FunctionNameAwareというインターフェースを継承しているからです。

今回はそこまでせずに、HandlerMethodのdescriptionを取得します。

//コントローラーの動作前
    @Override
    public boolean preHandle (HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

        String desc = "";
        if(handler instanceof HandlerMethod){
           desc = ((HandlerMethod)handler).toString();
        }

        log.info("処理開始" + desc);
        return true;
    }

    //コントローラーの操作後
    @Override
    public void postHandle (HttpServletRequest request, HttpServletResponse response, Object handler,
                            @Nullable ModelAndView modelAndView) throws Exception {
        String desc = "";
        if(handler instanceof HandlerMethod){
            desc = ((HandlerMethod)handler).toString();
        }

        log.info("処理終了" + desc);
    }

ログを確認してみます

2022-02-22 02:28:59.792  INFO 7192 --- [nio-8080-exec-1] com.volkruss.misaka.aop.RequestTracking  : 処理開始com.volkruss.misaka.web.controller.shop.ShopController#home()

2022-02-22 02:28:59.855  INFO 7192 --- [nio-8080-exec-1] com.volkruss.misaka.aop.RequestTracking  : 処理終了com.volkruss.misaka.web.controller.shop.ShopController#home()

2022-02-22 02:32:44.174  INFO 7192 --- [nio-8080-exec-6] com.volkruss.misaka.aop.RequestTracking  : 処理開始com.volkruss.misaka.web.controller.shop.ShopController#track()

2022-02-22 02:32:44.175  INFO 7192 --- [nio-8080-exec-6] com.volkruss.misaka.aop.RequestTracking  : 処理終了com.volkruss.misaka.web.controller.shop.ShopController#track()

共通的な処理なので抽象クラスに実装して、抽象クラスを継承する形にしてみます。まずはHandlerInterceptorを実装した抽象クラスを作成して、HandlerMethodのdescriptionを取得するメソッドを定義します。

public abstract class AbstractInterceptor implements HandlerInterceptor {

    protected String getHandlerMethodDesc(Object handler){
        String result = "";
        if(handler instanceof HandlerMethod){
            result = ((HandlerMethod)handler).toString();
        }
        return result;
    }
}

継承したクラスではHandlerInterceptorインターフェースのメソッドをオーバーライドします

@Component
@Slf4j
public class RequestTracking extends AbstractInterceptor {

    //コントローラーの動作前
    @Override
    public boolean preHandle (HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        log.info("処理開始" + this.getHandlerMethodDesc(handler));
        return true;
    }

    //コントローラーの操作後
    @Override
    public void postHandle (HttpServletRequest request, HttpServletResponse response, Object handler,
                            @Nullable ModelAndView modelAndView) throws Exception {
        log.info("処理終了" + this.getHandlerMethodDesc(handler));
    }
}

このインターセプタはメソッド名を特定しますが、もしもメソッド名なんか特定しないよってインターセプタもあったりする場合などもあるかと思います。

そうすると抽象クラスに定義するのが不自然になったりするので、そこは臨機応変に実装をします。

処理時間の計測

参考書を参考に処理時間を図ります。処理にかかった秒数をログ出力します。

@Component
@Slf4j
public class RequestTracking extends AbstractInterceptor {

    private static final ThreadLocal<Long> startTimeHolder = new ThreadLocal<>();

    //コントローラーの動作前
    @Override
    public boolean preHandle (HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        long beforeTime = System.nanoTime();
        startTimeHolder.set(beforeTime);

        log.info("処理開始" + this.getHandlerMethodDesc(handler));
        return true;
    }

    //コントローラーの操作後
    @Override
    public void postHandle (HttpServletRequest request, HttpServletResponse response, Object handler,
                            @Nullable ModelAndView modelAndView) throws Exception {
        long beforTime = startTimeHolder.get();
        long totalTime = System.nanoTime() - beforTime;
        long sec = TimeUnit.NANOSECONDS.toSeconds(totalTime);

        log.info("処理時間" + sec + " 秒 " + "処理終了" + this.getHandlerMethodDesc(handler));
    }
}

デバッグして処理を止めて時間を計測しました

2022-02-22 03:16:08.707  INFO 9300 --- [nio-8080-exec-1] com.volkruss.misaka.aop.RequestTracking  : 処理開始com.volkruss.misaka.web.controller.shop.ShopController#home()


2022-02-22 03:16:18.273  INFO 9300 --- [nio-8080-exec-1] com.volkruss.misaka.aop.RequestTracking  : 処理時間9 秒 処理終了com.volkruss.misaka.web.controller.shop.ShopController#home()

他にもリクエストの情報にアクセスできるので参考書ではトラッキングIDなどもログに出力しています。

ログ出力 | 現場至上主義 Spring Boot2 徹底活用