LastaFluteのアプリログ

LastaFluteが出力するアプリケーションのログ (開発、本番含めて) について

LastaFlute
ログにこだわるLastaFlute

LastaFluteのログ概要

LastaFluteのデフォルトのロギング思想は、おおよそこのようになっています。

ロギングフレームワークについて

ロギングフレームワークはこちら:

ログファサード
Slf4j (DBFluteなどもこちらを利用)
ログライブラリ
Logback

例外とログレベルとの関係

アプリの中で発生した例外とログレベルとの関係はこちら:

開拓の例外ハンドリング
バリデーションエラー
DEBUG (ここで、ユーザー入力のバリデーションのことを指している)
業務例外
INFO (ただし、ログイン認証は含まない)
クライアント例外
INFO (システム項目のバリデーションも含む)
システム例外
ERROR

特徴としては:

例外でも正常なイベントであればINFOでは出さない
例えば、ユーザー入力のバリデーションエラーとか、ログイン認証など。独自の例外でも、throwするときに withoutInfo() メソッドでINFOを抑えることができる。
もし、残しておきたいのであれば、流量が膨大なので専用のログファイルの方が良い
(そういうもの以外の)業務例外はINFOで出す
業務例外は、グレーゾーンもあるし、業務改善も必要かもしれないのでINFOで。
ただ、スタックトレースで通知ログが埋もれてしまわないように、行数を絞り込んで必要な部分だけにして小さく出す。 (ルート例外は10行、ネスト例外は3行など)
クライアント例外はINFOで出す
クライアントバグの可能性を分析するため、サーバーでINFOで残す。 例えば、ブラウザ上の JavaScript などであれば、クライアントでログを残せない可能性もあるため。 また、公開サーバーであれば、セキュリティ上あまり詳しい情報をレスポンスで戻さないほうが良いため。
ただ、公開アプリのときに "いたずらリクエスト" で大量発生する可能性はあるので、それが問題になるようであれば、クライアント例外もINFOで出さないように設定の変更を検討すべし。

ログレベルとログファイルの関係

ログレベルと出力されるログファイルの関係はこちら:

DEBUG
app_[アプリ名].log (開発用のログ、本番では出力されない)
INFO
app_[アプリ名].log (Jobの起動/終了、業務例外、クライアントエラーなども含む)
WARN
app_[アプリ名].log (SQL発行し過ぎとか、続行するけど後で直そう的な警告)
ERROR
app_[アプリ名].log + error_[アプリ名].log (NullPointerとか)

特徴としては:

  • INFO以上で本番に出力される (Jobの起動/終了、業務例外やクライアントエラー次第)
  • app_ログファイルの流量はあまり多くないことを想定 (ただし、業務例外やクライアントエラー次第)
  • ERRORだけは、緊急性の高いものということで専用ファイルにも出力される
  • WARNだけの専用ファイルは作っていないが、アプリで必要だと思ったら追加してもOK

エラーログのブランディング

エラーログに出力されたものは、ディベロッパーによる対応が必要なものである というブランドをキープすることに重点を置いたロギングデザインです。

ざっくりログは、大きく三つに分かれます。

  • ディベロッパーの対応が "要る" もの
  • ディベロッパーの対応が "要らない" もの
  • ディベロッパーの対応が "要るかわからない" もの

"要るかわからない" の扱いが難しいところです。要るかわからないものがエラーログに出力されると... おっ、エラーが出た！デバッグするぞー...なーんだ単なる業務的なレアケースじゃん を繰り返し、そのうちエラーログを垂れ流す エラーログ完全無視パターン 状態になってしまいがちです。 もちろん、人間的な運用でそうならないようにすることもできますが、それはそれでなかなか難しい面もあるでしょう。

なので、要るかわからないものは、通知ログの方に入れます。 その代り、本番運用で通知ログへの意識も持っておくことが前提です。 業務例外やクライアントエラーでも、実質的に対応が必要になうことも稀にありますし。

厳密には、運用しながら微調整することが必要でしょう。業務例外やクライアントエラーではなく、システム例外であっても、状況に寄っては対応が不要になるものもあるかもしれません。 固定的に判断できるものをピンポイントでエラーではなく通知の方に寄せていく運用があると良いです。

特殊なログとログファイルの関係

メール送信内容のログや、リクエストのIN/OUTのログなどは:

ActionやJSONの微調整 - ActionのInOutのログを出力する？
メール送信内容
mail_[アプリ名].log (すごい流量)
リクエストのIN/OUT
(inout_[アプリ名].log) (すごい流量、デフォルトでは設定されていない)

特徴としては:

  • app_[アプリ名].logでは出力されず、独立している
  • MailFluteでメール送信すれば、自然と出力されるようになっている
  • IN/OUTログはオプションなので、ログ設定を手動でする必要がある

ログファイルのローテーション

LastaFluteのExampleデフォルトでは、日付ごとにローテーションされるようになっていますが、この辺はアプリ要件に合わせて修正しましょう。

ログ設定の環境切り替え

[app]_env.propertiesで基本的なログ設定

[app]_env.properties にて、基本的なログ設定ができるようになっています。 よって、自然と環境切り替えができるようになっています。

LastaFluteの環境切り替え
log.level
ログレベル (debug, info)
log.console.level
コンソールに出力するログのログレベル (本番ではoffにしたいため独立)
log.file.basedir
ログファイルの出力先ディレクトリ

integration, production など環境ごとに設定がありますので、それぞれ適切に設定しましょう。 

e.g. set appender and logger for in-out logging @[app]_env.properties
# ----------------------------------------------------------
#                                                       Log
#                                                      -----
# The log level for logback
log.level = debug

# The log console level for logback
log.console.level = debug

# The log file basedir
log.file.basedir = /tmp/lastaflute/harbor

他にも、環境切り替えをしたい項目があれば、logback.xml の方で定義すると良いでしょう。

環境切り替えの仕組み

なぜ、logback.xml の設定が、[app]_env.properties で利用できるのでしょうか？

logback.xml の方で、[app]_env.properties を読み込むように定義しているからです。 

e.g. log property definition of harbor project @logback.xml
<configuration>
  <property resource="harbor_env.properties" />
  <property resource="harbor_env_${lasta.env}.properties" />
  <property name="domain.name" value="harbor"/>
  <property name="log.level" value="${log.level:-debug}"/>
  <property name="log.pattern" value="%d [%t] %-5p \\(%C{0}@%M\\(\\):%L\\) - %m%n"/>
  <property name="log.file.basedir" value="${log.file.basedir:-/tmp/lastaflute/undefinedbasedir}"/>
  <property name="backup.date.suffix" value="_%d{yyyyMMdd}"/>
  <property name="backup.max.history" value="180"/>

  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>${log.console.level}</level></filter>
  </appender>

  ...

なので、環境切り替え項目を追加したい場合は、そのまま properties で定義して、そのキー値を logback.xml の中で使ってしまえばOKです。

ただ、properties を LastaFlute 以外も読み込んでいるということになるので、あまり "あれもこれも" logback.xml から参照するというのはやらないほうが良いでしょう。logback専用のプロパティであることがわかるように、logbackから参照するプロパティは log. で始まるキー値にしておきましょう。

logback.xml of シングルプロジェクト

logback.xmlの置き場所

src/main/resources 配下に logback.xml がひとつあって、それがすべてです。 property、appender, logger がすべて入っています。 

e.g. logback.xml of harbor project @Directory
lastaflute-example-harbor
 |-src/main/java
 |-src/main/resources
 |  |-...
 |  |-logback.xml
 |
...

環境切り替えは、[app]_env.properties でやるので、logback.xml 自体が環境ごとに複数のファイルになることはありません。(そういう風にならないように設定していきましょう)

logback.xmlの中身

ロギング設定のざっくりおさらい:

property定義
logback.xml内で利用する定数宣言のようなもの
appender定義
ログの出力設定、どのファイルにどのように出力するなど
logger定義
どのパッケージのログを、どのappenderで出力するかの関連付け

一ファイルなので、すべての定義が入っています。 

e.g. logback definition of harbor project @logback.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<!-- _/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/ -->
<!-- Harbor logging settings for All Environments -->
<!-- _/_/_/_/_/_/_/_/_/_/ -->
<configuration>
  <property resource="harbor_env.properties" />
  <property resource="harbor_env_${lasta.env}.properties" />
  <property name="domain.name" value="harbor"/>
  <property name="log.level" value="${log.level:-debug}"/>
  <property name="log.pattern" value="%d [%t] %-5p \\(%C{0}@%M\\(\\):%L\\) - %m%n"/>
  <property name="log.file.basedir" value="${log.file.basedir:-/tmp/lastaflute/undefinedbasedir}"/>
  <property name="backup.date.suffix" value="_%d{yyyyMMdd}"/>
  <property name="backup.max.history" value="180"/>

  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>${log.console.level}</level></filter>
  </appender>
  <appender name="appfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/app_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/app_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>
  <appender name="errorfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/error_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>ERROR</level></filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/error_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>
  <appender name="mailfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/mail_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/mail_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>

  <logger name="org.dbflute" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="org.lastaflute" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="org.docksidestage" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="mailflute.sending" additivity="false" level="${log.level}">
    <appender-ref ref="mailfile"/>
  </logger>
  <root level="error">
    <appender-ref ref="console"/><appender-ref ref="errorfile"/>
  </root>
</configuration>
  • logger の org.docksidestage は、実際にはアプリのパッケージ名に変更される

logback.xml of マルチプロジェクト

logback.xmlの置き場所

それぞれのwebアプリプロジェクトの src/main/resources 配下に logback.xml があり、その中から参照する 部品的なxml が、 common プロジェクトに置いてあります。 

e.g. logback.xml in multi project @Directory
lastaflute-example-maihama
 |-maihama-base
 |
 |-maihama-common
 |  |-src/main/java
 |  |-src/main/resources
 |  |  |-logparts // 共通のロギング定義
 |  |  |  |-logback_appender.xml
 |  |  |  |-logback_logger.xml
 |  |  |  |-logback_property.xml
 |  |  |-...
 |
 |-maihama-dockside
 |  |-src/main/java
 |  |-src/main/resources
 |  |  |-...
 |  |  |-logback.xml
 |  ...
 |
 |-maihama-hangar
 |  |-src/main/java
 |  |-src/main/resources
 |  |  |-...
 |  |  |-logback.xml
 |  ...
...

logback.xmlの中身

それぞれのwebアプリの logback.xml の中から、common の部品的なxmlを include しています。 また、webアプリの properties を優先利用するために、logback_property.xml の宣言の後に、property宣言しています。 

e.g. logback definition of dockside project @logback.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<!-- _/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_ -->
<!-- Dockside logging settings for All Environments -->
<!-- _/_/_/_/_/_/_/_/_/_/_ -->
<configuration>
  <include resource="logparts/logback_property.xml" />
  <property resource="dockside_env.properties" />
  <property resource="dockside_env_${lasta.env}.properties" />
  <property resource="dockside_config.properties" />

  <!-- define your properties here
  e.g. <property name="sea.land" value="${piary.bonvo:-amba}"/> -->

  <include resource="logparts/logback_appender.xml" />

  <!-- define your additional appenders here
  e.g. <appender name="sea" class="land.PiaryAppender">... -->

  <include resource="logparts/logback_logger.xml" />

  <!-- define your additional loggers here
  e.g. <logger name="sea.land.piary.bonvo" additivity="false" level="${log.level}">... -->
</configuration>

logback_property.xmlの中身

どのwebアプリでも共通の property が定義されています。 

e.g. property definition of common project @logback_property.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<!-- _/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_ -->
<!-- Maihama logging property settings for All Environments -->
<!-- _/_/_/_/_/_/_/_/_/_/_ -->
<included>
  <property resource="maihama_env.properties" />
  <property resource="maihama_env_${lasta.env}.properties" />
  <property resource="maihama_config.properties" />
  <property name="domain.name" value="${domain.name:-maihama}"/>
  <property name="log.level" value="${log.level:-debug}"/>
  <property name="log.pattern" value="%d [%t] %-5p \\(%C{0}@%M\\(\\):%L\\) - %m%n"/>
  <property name="log.file.basedir" value="${log.file.basedir:-/tmp/lastaflute/undefinedbasedir}"/>
  <property name="backup.date.suffix" value="_%d{yyyyMMdd}"/>
  <property name="backup.max.history" value="180"/>
</included>

logback_appender.xmlの中身

どのwebアプリでも共通の appender が定義されています。 

e.g. appender definition of common project @logback_appender.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<!-- _/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_ -->
<!-- Maihama logging appender settings for All Environments -->
<!-- _/_/_/_/_/_/_/_/_/_/_ -->
<included>
  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>${log.console.level}</level></filter>
  </appender>
  <appender name="appfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/app_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/app_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>
  <appender name="errorfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/error_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>ERROR</level></filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/error_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>
  <appender name="mailfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log.file.basedir}/mail_${domain.name}.log</File>
    <Append>true</Append>
    <encoder><pattern>${log.pattern}</pattern></encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log.file.basedir}/backup/mail_${domain.name}${backup.date.suffix}.log</fileNamePattern>
      <maxHistory>${backup.max.history}</maxHistory>
    </rollingPolicy>
  </appender>
</included>

logback_logger.xmlの中身

どのwebアプリでも共通の logger が定義されています。 

e.g. logger definition of common project @logback_logger.xml
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE logback>
<!-- _/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_/_ -->
<!-- Maihama logging logger settings for All Environments -->
<!-- _/_/_/_/_/_/_/_/_/_/_ -->
<included>
  <logger name="org.dbflute" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="org.lastaflute" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="org.docksidestage" additivity="false" level="${log.level}">
    <appender-ref ref="console"/><appender-ref ref="appfile"/><appender-ref ref="errorfile"/>
  </logger>
  <logger name="mailflute.sending" additivity="false" level="${log.level}">
    <appender-ref ref="mailfile"/>
  </logger>
  <root level="error">
    <appender-ref ref="console"/><appender-ref ref="errorfile"/>
  </root>
</included>