Log4j の DailyRollingFileAppender を使用したログローテートが変。
現象
Log4j の DailyRollingFileAppender を使用したログ出力において、前日のログファイルに対してログが出力される。
例えば 2004-03-15 に起動された場合、ログファイル hoge.log に出力される。
$ ls -l hoge* -rwx------ 1 any hoge 37683 Mar 15 18:30 hoge.log
日付が変わり、2004-03-16 になると 前日のログがバックアップされる。
$ ls -l hoge* -rwx------ 1 any hoge 37683 Mar 16 00:00 hoge.log.2004-03-15 <-- バックアップされた。 -rwx------ 1 any hoge 0 Mar 16 00:00 hoge.log <-- 以降はこちらに出力されるはず。
以降のログは hoge.log に出力されるはずなのに、なぜか hoge.log.2004-03-15 にも出力されてしまう。
$ ls -l hoge* -rwx------ 1 any hoge 193423 Mar 16 01:12 hoge.log.2004-03-15 <-- なぜかここに出力される。 -rwx------ 1 any hoge 83433 Mar 16 01:03 hoge.log <-- こっちにもすこし出力されている。
調査
単体試験で以下のようなテストを行った。
- テストAPを起動、複数スレッドよりログを出力しまくる。
- date コマンドにより時間を調整、システム上の日付を変更する。
スレッド数に関係なく、正常にログが出力されることを確認。
次に複数プロセスによる実行を行ってみた。
- テストAPを同時に２つ起動、複数スレッドよりログを出力しまくる。
- date コマンドにより時間を調整、システム上の日付を変更する。
今回の障害と同じような現象が発生した。
考察
複数プロセスがログを出力する場合はここにあるように
SocketAppenderを使用すれば解決できるとなっている。
なので、上記の障害も同様の方法で解決できそう。
ただ何故 Tomcat でこの障害が発生するのかは不明。
複数コンテキストが存在し、同じログファイルに対してログ出力した場合は複数のClassLoader毎にファイルをオープンし、複数プロセスの書き込みと同じ現象がが発生するのはわかるけど、今回は１つしかコンテキストをデプロイしていない。
ためしに ClassLoader のテストを行うため、Contextの WEB-INF/lib 配下に配置していた log4j-1.2.8 を CATAINA_HOME 配下の shared/lib に移動してみた。
WEB-INF/lib/log4j-1.2.8.jar ---> $CATALINA_HOME/shared/lib/log4j-1.2.8.jar
動かしてみたところ正常にログローテートされた。
