リクエストの全記録、InOutログ

LastaFlute

概要
ログの出し方
どんなログが出力されるか？

概要

トラブル対応のときのために、本番環境でもActionのリクエストとレスポンスの内容を残しておきたい場合は、 LastaFluteにてそれら情報を専用のログファイルに出力することができます(@since LastaFlute-1.0.0)。 (もちろん、若干のパフォーマンス劣化が発生する可能性があるので、不要であればやらないほうが良いです)

e.g. in-out logging contents @inout_[app].log
// これは、HtmlResponseのときのログ
2017-08-20 00:16:08,784 [qtp2068434592-11] INFO  (InOutLogger@log():50) - gET /signin/ SigninAction@index() (2017-08-20 00:16:06.834) [00m01s950ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...Forwarding to /signin/signin.html)
2017-08-20 00:16:34,321 [qtp2068434592-15] INFO  (InOutLogger@log():50) - gET /member/list/ MemberListAction@index() (2017-08-20 00:16:33.946) [00m00s375ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...Forwarding to /member/member_list.html) sqlCount:{total=2, selectCB=2}
2017-08-20 00:16:49,572 [qtp2068434592-11] INFO  (InOutLogger@log():50) - POST /member/edit/ MemberEditAction@update() (2017-08-20 00:16:49.491) [00m00s081ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} *ValidationErrorException #5fd42ca requestParameter:{lastaflute.action.TRANSACTION_TOKEN=a30cdf490b0f7b831507d84730d8d288, birthdate=1965-03-03, versionNo=0, memberName=, memberStatus=FML, update=Update, memberAccount=Pixy, memberId=1, previousStatus=FML} responseBody:(...Forwarding to /member/member_edit.html)

// これは、JsonResponseのときのログ
2017-08-20 01:16:36,433 [qtp2068434592-17] INFO  (InOutLogger@log():50) - POST /wx/request/json/body/ WxRequestJsonBodyAction@index() (2017-08-20 01:16:36.312) [00m00s121ms] {Apache-HttpClient/4.5.2 (Java/1.8.0_131)}
requestBody:{sea: "mystic"}
responseBody:
{
  "body": {
    "sea": "mystic",
    "land": null,
    "piari": null,
    "bonvo": null,
    "dstore": null
  }
}

LastaFlute の InOutLoggerクラスで処理されます。

InOutLogger.java | github

ログの出し方

ActionAdjustmentProvider にて、設定できます。

ActionやJSONの微調整 - ActionのInOutのログを出力する？

isUseInOutLogging()をオーバーライド

isUseInOutLogging() をオーバーライドして、true にすると有効になります。

logbackの設定を追加

出力される Logger (Slf4j上の) の名前は、lastaflute.inout になります。大量のログになるはずなので(ハードディスクの容量にも気をつけましょう)、普段のアプリログに混ぜないためです。 logbackで何も設定しなければ、どこにも出力はされませんので、ログファイルの設定をしましょう。

e.g. set appender and logger for in-out logging @logback.xml
  <appender name="inoutfile" class="ch.qos.logback.core.rolling.RollingFileAppender"&gt;
    <File&gt;${log.file.basedir}/inout_${domain.name}.log</File&gt;
    <Append&gt;true</Append&gt;
    <encoder&gt;<pattern&gt;${log.pattern}</pattern&gt;</encoder&gt;
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"&gt;
      <fileNamePattern&gt;${log.file.basedir}/backup/inout_${domain.name}${backup.date.suffix}.log</fileNamePattern&gt;
      <maxHistory&gt;${backup.max.history}</maxHistory&gt;
    </rollingPolicy&gt;
  </appender&gt;

  ...

  <logger name="lastaflute.inout" additivity="false" level="${log.level}"&gt;
    <appender-ref ref="inoutfile"/&gt;
  </logger&gt;

InOutのログを調整する？

InOutLogOptionで、InOutのログを調整できます。(isUseInOutLogging()がtrueであることが前提)

非同期: 先の通り不要だと思われるが、いざってときのために
responseBody抑制: あまりにデカすぎるしレスポンスは要らないってとき
requestParameterフィルター: 暗号化するとか!? いざってときのために
requestBodyフィルター: 暗号化するとか!? いざってときのために
responseBodyフィルター: 暗号化するとか!? いざってときのために

このメソッドは、何度も呼び出される可能性があるので、InOutLogOption自体はインスタンス変数などでキャッシュしておくと良いでしょう。

どんなログが出力されるか？

e.g. in-out logging contents @inout_[app].log
// これは、HtmlResponseのときのログ
2017-08-20 00:16:08,784 [qtp2068434592-11] INFO  (InOutLogger@log():50) - gET /signin/ SigninAction@index() (2017-08-20 00:16:06.834) [00m01s950ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...Forwarding to /signin/signin.html)
2017-08-20 00:16:34,321 [qtp2068434592-15] INFO  (InOutLogger@log():50) - gET /member/list/ MemberListAction@index() (2017-08-20 00:16:33.946) [00m00s375ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} responseBody:(...Forwarding to /member/member_list.html) sqlCount:{total=2, selectCB=2}
2017-08-20 00:16:49,572 [qtp2068434592-11] INFO  (InOutLogger@log():50) - POST /member/edit/ MemberEditAction@update() (2017-08-20 00:16:49.491) [00m00s081ms] {Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:5...} *ValidationErrorException #5fd42ca requestParameter:{lastaflute.action.TRANSACTION_TOKEN=a30cdf490b0f7b831507d84730d8d288, birthdate=1965-03-03, versionNo=0, memberName=, memberStatus=FML, update=Update, memberAccount=Pixy, memberId=1, previousStatus=FML} responseBody:(...Forwarding to /member/member_edit.html)

// これは、JsonResponseのときのログ
2017-08-20 01:16:36,433 [qtp2068434592-17] INFO  (InOutLogger@log():50) - POST /wx/request/json/body/ WxRequestJsonBodyAction@index() (2017-08-20 01:16:36.312) [00m00s121ms] {Apache-HttpClient/4.5.2 (Java/1.8.0_131)}
requestBody:{sea: "mystic"}
responseBody:
{
  "body": {
    "sea": "mystic",
    "land": null,
    "piari": null,
    "bonvo": null,
    "dstore": null
  }
}

HTTPメソッド (gET or POST or ...)
リクエストURLやActionクラスの名前
開始日時やコスト時間 (ログのヘッダーはログ出力日時、つまり実質的に終了日時なので、別途開始日時が必要)
UserAgent (あまりに長い可能性があるので、最初の限られた文字数分だけ)
例外のときは例外クラスも (詳細やスタックトレースは、エラーログの方を参照。ハッシュコードで辿れる)
リクエストパラメーター (requestParameter) (gETやPOSTなどのFormパラメーターのときなど)
リクエストボディ (requestBody) (JSONによるリクエストのときなど)
レスポンスボディ (responseBody) (HTMLレスポンスや、JSONレスポンスのとき)
SQLの発行回数 (sqlCount) (SQLを発行していれば)
メールの送信回数 (mailCount) (メールを送信していれば)

出し始めたらキリがないので、このくらいにしております。(あくまで本番でいざってときのデバッグに役に立つ代表的なものを出しているつもりです)

ログ出力は非同期ではありませんが、HtmlResponseのときのリダイレクトを除き、レスポンスを書き込んだ後にログ出力なのでリクエスト側に遅延は発生しません(アプリケーションサーバーによって挙動が変わるかもしれませんが、TomcatとJettyで確認しています)。 InOutLogOptionにて、非同期にすることもできます。

ヘッダーはデフォルトでは出していませんが、InOutLogOptionにて項目指定で出力されます。(@since LastaFlute-1.1.2)