Spring MVCで所要時間付きのリクエストログを出力する

Spring MVCのアプリケーションでリクエストログを出力するには CommonsRequestLoggingFilter を使うと簡単です。

リクエストログの設定

Spring Bootの場合は以下のように設定します。

@Configuration
public class AppConfiguration {
  @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;
  }
}

リクエストログで出力する項目はSetterで設定できます。上記ではクライアント情報、クエリパラメータ、ヘッダ、ペイロードをすべて出力しています。詳しくは AbstractRequestLoggingFilter を参照してください。

リクエストログはDEBUGレベルで出力されるため、ログレベルを設定しておきます。

# application.yml
logging.level:
  org.springframework.web.filter.CommonsRequestLoggingFilter: DEBUG

以下のようなログが出力されます。

2017-05-16 05:40:36.008 DEBUG 8760 --- [thread] o.s.w.f.CommonsRequestLoggingFilter      : Before request [uri=/example;client=127.0.0.1;headers={Connection=[keep-alive], Host=[localhost:8080], Content-Length=[15], Content-Type=[application/json;charset=UTF-8]}]
2017-05-16 05:40:36.274 DEBUG 8760 --- [thread] o.s.w.f.CommonsRequestLoggingFilter      : After request [uri=/example;client=127.0.0.1;headers={Connection=[keep-alive], Host=[localhost:8080], Content-Length=[15], Content-Type=[application/json;charset=UTF-8]};payload={"key":"value"}]

リクエストログに所要時間を付ける

レスポンスタイムを集計するため、リクエストログに所要時間を付けてみましょう。

AbstractRequestLoggingFilter をカスタマイズしたフィルタクラスを作成します。

@Slf4j
public class RequestTimeLoggingFilter extends AbstractRequestLoggingFilter {
  private static final String ATTRIBUTE_KEY = RequestTimeLoggingFilter.class.getName();

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

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

  @Override
  protected void afterRequest(HttpServletRequest request, String message) {
    val beforeNanoSec = request.getAttribute(ATTRIBUTE_KEY);
    if (beforeNanoSec instanceof Long) {
      val elapsedNanoSec = System.nanoTime() - (long) beforeNanoSec;
      val elapsedMilliSec = NANOSECONDS.toMillis(elapsedNanoSec);
      log.debug("Elapsed {} ms {}", elapsedMilliSec, message);
    } else {
      log.debug(message);
    }
  }
}

先ほどと同様にBeanを登録します。

@Configuration
public class AppConfiguration {
  @Bean
  public RequestTimeLoggingFilter requestLoggingFilter() {
    RequestTimeLoggingFilter filter = new RequestTimeLoggingFilter();
    // ログ出力項目の設定...
    return filter;
  }
}

ログレベルを設定します。

# application.yml
logging.level:
  com.example.RequestTimeLoggingFilter: DEBUG

以下のようなログが出力されます。

2017-05-16 05:40:36.008 DEBUG 8760 --- [thread] c.e.RequestTimeLoggingFilter      : Before request [uri=/example;client=127.0.0.1;headers={Connection=[keep-alive], Host=[localhost:8080], Content-Length=[15], Content-Type=[application/json;charset=UTF-8]}]
2017-05-16 05:40:36.274 DEBUG 8760 --- [thread] c.e.RequestTimeLoggingFilter      : Elapsed 246 ms After request [uri=/example;client=127.0.0.1;headers={Connection=[keep-alive], Host=[localhost:8080], Content-Length=[15], Content-Type=[application/json;charset=UTF-8]};payload={"key":"value"}]