GeekFactory

int128.hatenablog.com

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"}]

まとめ

Spring MVCのアプリケーションでリクエストログを出力するには CommonsRequestLoggingFilter クラスを利用すると簡単です。さらに、 AbstractRequestLoggingFilter をカスタマイズすると所要時間等を入れることもできます。

Spring Bootアプリケーションのログファイル運用

Spring Bootアプリケーションのログファイル運用についてメモ。

前提

Spring Bootのログ

Spring Bootのログはデフォルトでは標準出力に出力される。ログファイルを出力するにはapplication.ymlで設定するか、JVMに起動オプションを渡す。

java -jar app.jar --logging.path="$LOG_PATH"

上記を指定すると、10MBのサイズでローテーションされる。最大で8世代まで保持される。

  • spring.log ←最も新しい
  • spring.log.1 (10MB)
  • spring.log.2 (10MB)
  • spring.log.7 (10MB) ←最も古い

最大世代に達した場合は最も大きい番号のログファイルが削除されて、番号がシフトされる。上記の場合は .7 が削除されて、.6.7 にリネームされる。

FluentdやCloudWatch Logsでログを収集する場合は spring.log をtailすればよい。8世代を超えたものは自動的に削除されるので、ガベージは気にしなくてよい。

GCのログ

GCガベージコレクション)のログはデフォルトでは出力されない。ログファイルを出力するにはJVMに起動オプションを渡す必要がある。

JAVA_OPTS=(
  "-Xloggc:$LOG_PATH/gc.log"
  "-XX:+UseGCLogFileRotation"
  "-XX:GCLogFileSize=10M"
  "-XX:NumberOfGCLogFiles=5"
  "-XX:+PrintGCDetails"
  "-XX:+PrintGCDateStamps"
)

java "${JAVA_OPTS[@]}" -jar app.jar

上記を指定すると、10MBのサイズでローテーションされる。最大で5世代まで保持される。

  • gc.log.0 ←古いもの
  • gc.log.1.current ←現在アクティブなもの

現在アクティブなものに .current が付与される。最大世代に達した場合は小さい番号から再利用される。

FluentdやCloudWatch Logsでログを収集する場合は gc.log.*.current をtailすればよい。8世代を超えたものは自動的に削除されるので、ガベージは気にしなくてよい。

SetEnvIfでヘッダがない場合の条件の書き方

ApacheのSetEnvIfでヘッダがない場合の条件の書き方を調べてみました。下記のように正規表現^$ を指定すると、ヘッダなしにマッチしてくれます。

# x-forwarded-forヘッダがない場合、環境変数noelbを設定する
SetEnvIf x-forwarded-for "^$" noelb

例えば、ELBを経由するアクセスのみ認証を有効にしたい場合は下記のように設定します。

Satisfy Any

# 認証
AuthUserFile /example/.htpasswd
AuthName Example
AuthType Basic
require valid-user

# ELB経由でないアクセスは認証を外す
SetEnvIf x-forwarded-for "^$" noelb
Order Deny,Allow
Deny from all
Allow from env=noelb

なお、SetEnvIfはヘッダだけでなくリクエストURIなども書けるので、ヘルスチェックを認証から外す場合にも使えます。