投稿日： 2019年5月9日
最終更新日： 2023年3月28日

【SpringBoot2】リクエストの処理時間をログに出力する方法【AbstractRequestLoggingFilter】

YouTubeも見てね♪

【最新機種】GoPro hero11 Black

【日本国内正規品】 GoPro hero11 Black

created by Rinker

GoPro(ゴープロ)

¥65,800 (2023/05/21 15:37:31時点 Amazon調べ-詳細)

最新機種でVlogの思い出を撮影しよう！

ペヤングソースやきそば 120g×18個

created by Rinker

ペヤング

¥3,012 (2023/05/21 15:37:32時点 Amazon調べ-詳細)

とりあえず保存食として買っておけば間違いなし！

レッドブルエナジードリンク 250ml×24本

created by Rinker

Red Bull(レッドブル)

¥3,820 (2023/05/21 15:45:33時点 Amazon調べ-詳細)

翼を授けよう！

モンスターエナジー 355ml×24本 [エナジードリンク]

アサヒ飲料モンスターエナジー 355ml×24本 [エナジードリンク]

created by Rinker

モンスター

¥4,784 (2023/05/21 15:37:32時点 Amazon調べ-詳細)

脳を活性化させるにはこれ！

ドラゴンクエストメタリックモンスターズギャラリーメタルキング

created by Rinker

スクウェア・エニックス(SQUARE ENIX)

¥3,600 (2023/05/21 15:41:00時点 Amazon調べ-詳細)

みんな大好き経験値の塊をデスクに常備しておこう！

MOFT X 【新型ミニマム版】 iPhone対応スマホスタンド

created by Rinker

MOFT

¥2,880 (2023/05/21 15:37:34時点 Amazon調べ-詳細)

Amazon一番人気のスマホスタンド！カード類も収納出来てかさ張らないのでオススメです！

サンディスク microSD 128GB

サンディスク microSD 128GB UHS-I Class10 Nintendo Switch SanDisk Ultra SDSQUA4-128G-EPK

created by Rinker

SanDisk

¥1,874 (2023/05/21 15:40:44時点 Amazon調べ-詳細)

スマホからSwitchまで使える大容量MicroSDカード！

1 リクエストの所要時間をログに出そう
2 手順
3 終わりに

リクエストの所要時間をログに出そう

前回、SpringBoot2のCommonsRequestLoggingFilterと言う既存Filterを用いたリクエスト情報のログ出力についてご紹介しました。

参考

【RequestBody/RequestHeader】SpringBoot2でリクエスト情報をログに出力する方法【CommonsRequestLoggingFilter】

今回は、さらにもう一手間加え、リクエスト処理を完了するまでの時間をログに追加する方法をご紹介致します。

手順

AbstractRequestLoggingFilterの継承クラスを実装

まずは、AbstractRequestLoggingFilterを継承したクラスを用意しましょう。

package tech.blogenist.service.account.api.infrastructure.filter.millisec;

import javax.servlet.http.HttpServletRequest;

import org.springframework.web.filter.AbstractRequestLoggingFilter;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class RequestMilliSecFilter extends AbstractRequestLoggingFilter
{
    private final String BEFORE_REQUEST_MILLI_SEC_KEY = this.getClass().getName();

    @Override
    protected boolean shouldLog( HttpServletRequest request )
    {
        return log.isDebugEnabled();
    }

    @Override
    protected void beforeRequest( HttpServletRequest request, String message )
    {
        log.debug( message );
        request.setAttribute( BEFORE_REQUEST_MILLI_SEC_KEY, System.currentTimeMillis() );
    }

    @Override
    protected void afterRequest( HttpServletRequest request, String message )
    {
        Object beforeMilliTime = request.getAttribute( BEFORE_REQUEST_MILLI_SEC_KEY );
        if( beforeMilliTime instanceof Long )
        {
            long startMilliTime = ( long ) beforeMilliTime;
            long elapsedMilliTime = System.currentTimeMillis() - startMilliTime;
            log.debug( "latency {} ms {}", elapsedMilliTime, message );
        }else
        {
            log.debug( message );
        }
    }
}

package tech.blogenist.service.account.api.infrastructure.filter.millisec;

import javax.servlet.http.HttpServletRequest;

import org.springframework.web.filter.AbstractRequestLoggingFilter;

import lombok.extern.slf4j.Slf4j;

@Slf4j

public class RequestMilliSecFilter extends AbstractRequestLoggingFilter

{

private final String BEFORE_REQUEST_MILLI_SEC_KEY = this.getClass().getName();

@Override

protected boolean shouldLog( HttpServletRequest request )

{

return log.isDebugEnabled();

}

@Override

protected void beforeRequest( HttpServletRequest request, String message )

{

log.debug( message );

request.setAttribute( BEFORE_REQUEST_MILLI_SEC_KEY, System.currentTimeMillis() );

}

@Override

protected void afterRequest( HttpServletRequest request, String message )

{

Object beforeMilliTime = request.getAttribute( BEFORE_REQUEST_MILLI_SEC_KEY );

if( beforeMilliTime instanceof Long )

{

long startMilliTime = ( long ) beforeMilliTime;

long elapsedMilliTime = System.currentTimeMillis() - startMilliTime;

log.debug( "latency {} ms {}", elapsedMilliTime, message );

}else

{

log.debug( message );

}

Beanの追加

次に、前回利用した@Configurationがついたクラスを修正します。

package tech.blogenist.service.account.api.infrastructure.filter.config;

import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

import tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter;
import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.MdcXRequestIdFilter;
import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.ResponseHeaderAddXRequestIdFilter;

@Configuration
public class FilterConfig
{

    @Bean
    public MdcXRequestIdFilter mdcXRequestIdFilter()
    {
        MdcXRequestIdFilter filter = new MdcXRequestIdFilter();
        return filter;
    }

    @Bean
    public ResponseHeaderAddXRequestIdFilter responseHeaderAddXRequestIdFilter()
    {
        ResponseHeaderAddXRequestIdFilter filter = new ResponseHeaderAddXRequestIdFilter();
        return filter;
    }

    @Bean
    public RequestMilliSecFilter requestMilliSecFilter()
    {
        RequestMilliSecFilter filter = new RequestMilliSecFilter(); // CommonsRequestLoggingFilterから変更
        filter.setIncludeClientInfo( true );
        filter.setIncludeQueryString( true );
        filter.setIncludeHeaders( true );
        filter.setIncludePayload( true );
        return filter;
    }
}

package tech.blogenist.service.account.api.infrastructure.filter.config;

import org.springframework.context.annotation.Bean;

import org.springframework.context.annotation.Configuration;

import tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter;

import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.MdcXRequestIdFilter;

import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.ResponseHeaderAddXRequestIdFilter;

@Configuration

public class FilterConfig

{

@Bean

public MdcXRequestIdFilter mdcXRequestIdFilter()

{

MdcXRequestIdFilter filter = new MdcXRequestIdFilter();

return filter;

}

@Bean

public ResponseHeaderAddXRequestIdFilter responseHeaderAddXRequestIdFilter()

{

ResponseHeaderAddXRequestIdFilter filter = new ResponseHeaderAddXRequestIdFilter();

return filter;

}

@Bean

public RequestMilliSecFilter requestMilliSecFilter()

{

RequestMilliSecFilter filter = new RequestMilliSecFilter(); // CommonsRequestLoggingFilterから変更

filter.setIncludeClientInfo( true );

filter.setIncludeQueryString( true );

filter.setIncludeHeaders( true );

filter.setIncludePayload( true );

return filter;

}

これで準備は完了です。

確認

では、実際にリクエストを投げて確認してみましょう。

{  
   "timestamp":"2019-05-09T11:42:39.780+09:00",
   "level":"DEBUG",
   "thread":"http-nio-8080-exec-1",
   "mdc":{  
      "x-request-id":"b9edaaf7-036e-4a59-84fb-f23d35ad98fc"
   },
   "logger":"tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter",
   "message":"latency 56 ms After request [uri=/v1/accounts/10001/;client=0:0:0:0:0:0:0:1;headers=[host:\"localhost:8080\", connection:\"keep-alive\", user-agent:\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36\", header:\"fuga\", cache-control:\"no-cache\", postman-token:\"4b63ac31-571e-9fc4-c81b-eaaf2ce64ade\", accept:\"*/*\", accept-encoding:\"gzip, deflate, br\", accept-language:\"ja,en-US;q=0.9,en;q=0.8\", Content-Type:\"application/json;charset=UTF-8\"]]"
}

{

"timestamp":"2019-05-09T11:42:39.780+09:00",

"level":"DEBUG",

"thread":"http-nio-8080-exec-1",

"mdc":{

"x-request-id":"b9edaaf7-036e-4a59-84fb-f23d35ad98fc"

"logger":"tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter",

"message":"latency 56 ms After request [uri=/v1/accounts/10001/;client=0:0:0:0:0:0:0:1;headers=[host:\"localhost:8080\", connection:\"keep-alive\", user-agent:\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36\", header:\"fuga\", cache-control:\"no-cache\", postman-token:\"4b63ac31-571e-9fc4-c81b-eaaf2ce64ade\", accept:\"*/*\", accept-encoding:\"gzip, deflate, br\", accept-language:\"ja,en-US;q=0.9,en;q=0.8\", Content-Type:\"application/json;charset=UTF-8\"]]"

}

正常にlatencyにミリ秒が出力されるようになりましたね♪