【Spring Boot】リクエストのログ出力

SpringBoot

2021/09/19

ログ出力の基本

Spring Boot におけるログ出力については、別の記事にまとめてありますのでこちらを参考にしてください。

この記事ではリクエストの情報をログに出力する処理を個別に設定するのではなく、共通化することを考えていきます。

Interceptor

共通化する処理する方法の 1 つとして、Interceptor があります。 Interceptor の詳細については、こちらの記事を参考にしてください。

以下のようにリクエストの情報を出力する Interceptor を作成します。出力する内容は適宜変更してください。

LoggingHandlerInterceptor.java

public class LoggingHandlerInterceptor implements HandlerInterceptor {

  Logger logger = LoggerFactory.getLogger(LoggingHandlerInterceptor.class);

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
    String message = String.format("[%s] %-4s %s",
        request.getLocalAddr(), request.getMethod(), request.getRequestURI());
    logger.info(message);
    return true;
  }
}

作成した Interceptor を以下のように登録することで、指定したパスのリクエスト情報がログに出力されます。

WebMvcConfig.java

@Configuration
public class WebMvcConfig implements WebMvcConfigurer {

  @Bean
  LoggingHandlerInterceptor loggingHandlerInterceptor() {
    return new LoggingHandlerInterceptor();
  }

  @Override
  public void addInterceptors(InterceptorRegistry registry) {
    registry.addInterceptor(loggingHandlerInterceptor())
            .addPathPatterns("/api/**");
  }
}

出力例

[127.0.0.1] GET  /api/sample

Interceptor を利用する場合の注意点として、リクエストボディの情報はログに出力することができません。正確には、ここでリクエストボディの情報を読み込んでしまうと、後の処理で読み込み済みという扱いになりエラーとなってしまいます。

CommonsRequestLoggingFilter

以下のようにCommonsRequestLoggingFilterを Bean として（DI コンテナに）登録することで、リクエストについて決まったフォーマットのログが出力されるようになります。

WebMvcConfig.java

@Configuration
public class WebMvcConfig implements WebMvcConfigurer {

  @Bean
  public CommonsRequestLoggingFilter requestLoggingFilter() {
    CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
    filter.setIncludeClientInfo(true);
    filter.setIncludeQueryString(true);
    filter.setIncludeHeaders(true);
    filter.setIncludePayload(true);
    filter.setMaxPayloadLength(1024);
    return filter;
  }
}

ただし、ログレベルがDEBUGの場合のみ出力されるため、以下のように設定を追加してください。

application.yml

logging.level:
  org.springframework.web.filter.CommonsRequestLoggingFilter: DEBUG

setIncludeClientInfo()のように、出力する内容はメソッドにより設定できます。

メソッド	説明
`setIncludeClientInfo()`	IP アドレス、HTTP メソッド
`setIncludeQueryString()`	クエリパラメーター
`setIncludeHeaders()`	リクエストヘッダー
`setIncludePayload()`	リクエストボディ
`setMaxPayloadLength()`	リクエストボディの表示サイズ

以下はContent-Typeがapplication/jsonの場合の出力例です。

出力例

After request [POST /api, client=0:0:0:0:0:0:0:1, headers=[host:"localhost:8080", accept-encoding:"gzip, deflate, br", connection:"keep-alive", content-length:"110", Content-Type:"application/json;charset=UTF-8"], payload={
    "id": "0001",
    "name": "Tanaka",
    "age": 25,
}]

実際には Before request と After Request の 2 つが出力されます。詳細は割愛しますが、Before はリクエストの受信直後、After はレスポンスの送信直前くらいに考えてください。

基本的には同じなのですが、Before ではリクエストボディの情報が出力されません。理由については後述します。

ここでCommonsRequestLoggingFilterの実装をみてみます。

CommonsRequestLoggingFilter.java

public class CommonsRequestLoggingFilter extends AbstractRequestLoggingFilter {

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

  @Override
  protected void beforeRequest(HttpServletRequest request, String message) {
    logger.debug(message);
  }

  @Override
  protected void afterRequest(HttpServletRequest request, String message) {
    logger.debug(message);
  }
}

見ての通り実装はシンプルで、AbstractRequestLoggingFilterを継承しています。例えば Before の出力が不要な場合やログレベルを変更したい場合は、同じ構成でクラスを作成し、Bean として登録すればよいだけです。

MyCommonsRequestLoggingFileter.java

public class CommonsRequestLoggingFilter extends AbstractRequestLoggingFilter {

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

  @Override
  protected void beforeRequest(HttpServletRequest request, String message) {
    //不要のため削除
  }

  @Override
  protected void afterRequest(HttpServletRequest request, String message) {
    logger.info(message);  //ログレベルの変更
  }
}

OncePerRequestFilter

CommonsRequestLoggingFilterから出力されるメッセージフォーマットを変更したいなどをしたい場合は、OncePerRequestFilterを継承したクラスを作成します。先に言っておくと、果たしてここまでする必要があるのか、という疑問はありますが…。

CommonsRequestLoggingFilterが継承していたAbstractRequestLoggingFilterは、OncePerRequestFilterを継承しています。そのためAbstractRequestLoggingFilterを参考に作成していきます。

AbstractRequestLoggingFilterでログを出力しているのは以下のdoFilterInternal()です。

AbstractRequestLoggingFilter

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
    throws ServletException, IOException {

  boolean isFirstRequest = !isAsyncDispatch(request);
  HttpServletRequest requestToUse = request;

  //**ここがポイント**
  if (isIncludePayload() && isFirstRequest && !(request instanceof ContentCachingRequestWrapper)) {
    requestToUse = new ContentCachingRequestWrapper(request, getMaxPayloadLength());
  }

  boolean shouldLog = shouldLog(requestToUse);
  if (shouldLog && isFirstRequest) {
    //リクエスト直後の処理
    beforeRequest(requestToUse, getBeforeMessage(requestToUse));
  }
  try {
    //**ここがポイント**
    filterChain.doFilter(requestToUse, response);
  }
  finally {
    if (shouldLog && !isAsyncStarted(requestToUse)) {
      //レスポンス直前の処理
      afterRequest(requestToUse, getAfterMessage(requestToUse));
    }
  }
}

いろいろ記載がありますが、ログの出力は抽象メソッドであるbeforeRequest()とafterRequest()によって行われます。具体的なログの出力処理は継承先で定義されますが、getAfterMessage()とあるようにログのメッセージはAbstractRequestLoggingFilter内で作成されます。

さて、ここでポイントとなるのがContentCachingRequestWrapperです。これはリクエストをラップすることで、リクエストボディの情報をキャッシュできるようになります。

例えば以下のようにすることで、リクエストボディの内容をログに出力できるようになります。

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
    throws ServletException, IOException {

  //リクエストをキャッシュする
  ContentCachingRequestWrapper wrapper = new ContentCachingRequestWrapper(request);
  wrapper.getParameterNames();

  //リクストボディの内容を出力
  String requestBody = new String(wrapper.getContentAsByteArray(), wrapper.getCharacterEncoding());
  logger.info(requestBody);

  //次のフィルタへ
  filterChain.doFilter(wrapper, response);
}

ContentCachingRequestWrapperのgetParameterNames()を実行することにより、リクエストボディの内容が内部にキャッシュされます。キャッシュした内容はgetContentAsByteArray()で取得します。

フィルターチェインをするときにContentCachingRequestWrapperのオブジェクトを渡すことで、リクエストボディの内容を先に読んでいたとしても後続の処理でエラーにならなくなります。

キャッシュはgetParameterNames()以外に、getParameter()、getParameterMap()、getParameterValues()のいずれかで実行されます。ただし、HTTP メソッドが POST かつContent-Typeがapplication/x-www-form-urlencodedの場合に限ります。

Content-Typeがapplication/jsonの場合は以下のようにします。

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
    throws ServletException, IOException {

  ContentCachingRequestWrapper wrapper = new ContentCachingRequestWrapper(request);

  try {
    //次のフィルタへ
    filterChain.doFilter(wrapper, response);
  } finally {
    //リクストボディの内容を出力
    String requestBody = new String(wrapper.getContentAsByteArray(), wrapper.getCharacterEncoding());
    logger.info(requestBody);
  }
}

先程の例との違いは、キャッシュの処理がなく、ログの出力を Filter の後処理として定義します。

ここからは推測になってしまうのですが、データバインドする際にキャッシュする処理が行われているため、後処理でキャッシュした内容を読み込むことでログが出力できるのではないかと考えています。しかし、具体的にどこでどのようにキャッシュされているかのソースが見つからなかったため、あまり深く言及はしません。

CommonsRequestLoggingFilterの説明で、Before request でリクエストボディの情報が表示されなかったのは、キャッシュが実行されていないからです。 After request では、（おそらく）キャッシュが実行されているためリクエストボディの情報が表示されます。

【Spring Security】CORSの設定

SpringBoot

2024/03/09

【Spring Security】認証アーキテクチャ

SpringBoot

2024/03/08

【Spring Security】DBによる認証

SpringBoot

2024/03/06

【Spring Security】認証・認可の基礎

SpringBoot

2023/03/29

【Spring Security】はじめの一歩

SpringBoot

2023/03/20

ログ出力の基本 Interceptor CommonsRequestLoggingFilter OncePerRequestFilter