log4j(1.2.14以前)でRollingFileAppenderを使うと、ログ切替時にログが消失する場合がある。

log4jの問題というよりは、パーミッション設定の問題で、ログファイル自体には書き込み権限はあるが、ログファイルを出力するディレクトリに書き込み権限がない場合に起こります。

■ログファイルには、書き込み権限がある

taka@taka-VirtualBox:~/log4jtest$ ls -l logs/test.log
-rw-r--r-- 1 taka taka 0 2012-08-22 23:03 logs/test.log

■ログ出力ディレクトリには、書き込み権限がない

taka@taka-VirtualBox:~/log4jtest$ ls -l | grep logs
dr-xr-xr-x 2 taka taka   4096 2012-08-22 23:03 logs

通常はこのようなパーミッション設定にはしないのですが、実際のケースでは、owner権限は正しく設定できているが、group/other権限が正しくないというものでした。

ログファイルへの書き込み権限はあるので、追記は問題なく行えます。問題が起こるのは、ログファイルのサイズがMaximumFileSizeに達したときです。

ログファイルのサイズがMaximumFileSizeに達したときの動作は以下のようになります。

1. (存在すれば)test.log.(maxBackupIndex)を削除
2. test.log.nをtest.log.(n+1)にリネーム
3. test.logをtest.log.1にリネーム
4. test.logをクリア

バックアップファイルが存在しない状態の場合、3.から始まります。
3.の手順でtest.logをtest.log.1にリネームしようとするも、書き込み権限がないので、リネームが失敗します。
ここで終わればログが消失することはないのですが、その後ログを新たに書き込む準備として、4.の手順でtest.logをクリアしてしまうので、結果的に、空のtest.logが残るということになります。

RollingFileAppenderのソースをよくよく読んでみると、

http://svn.apache.org/repos/asf/logging/log4j/trunk/src/main/java/org/apache/log4j/RollingFileAppender.java

3.のリネームに失敗した場合、4.のログクリアの処理にはいかないようになっており、ログ消失は起きえません。
調べてみたところ、この事象は既知のバグで、log4j-1.2.15で既に修正されていました。

■log4j-1.2.15 Release Note
http://logging.apache.org/log4j/1.2/changes-report.html#a1.2.15

■Bug 41735
https://issues.apache.org/bugzilla/show_bug.cgi?id=41735

上記のテストはlog4j-1.2.9で行っていたために発生していましたが、
試しにlog4j-1.2.15にしてみたら、ログの消失は起きなくなっていました。
ただし、相変わらずリネームができないので、test.logに延々と追記し続けることになります。
というオチでした。

再現ソースを載せておきます。

■test.java

import org.apache.log4j.*;

public class test {
        public static void main(String[] args) {
                // Build Appender
                RollingFileAppender a = new RollingFileAppender();
                a.setLayout(new PatternLayout("%m%n"));
                a.setFile("logs/test.log");
                a.setMaximumFileSize(30);
                a.setMaxBackupIndex(3);
                a.activateOptions();

                // Get Logger
                Logger logger = Logger.getLogger(test.class);
                logger.addAppender(a);

                logger.debug("0123456789");
        }
}