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なども書けるので、ヘルスチェックを認証から外す場合にも使えます。