| Subject: | Files rotated on every message after long periods of inactivity |
Hi Mark,
thanks for your module, it's pretty popular in the Log4perl community.
A coworker discovered the other day that Log::Dispatch::FileRotate keeps
on rotating the logfile with every message if there hasn't been log
activity for several rotation periods.
For example, if the logfile is configured to rotate every hour, and
there's no log activity for 10 hours, the next 10 log messages will
trigger a log file rotation each. The problem is that _next_occurance()
doesn't weed out occurances that are expired.
I've attached a patch to fix the problem, along with test cases that
reproduce the bug. Would be great if you could apply it and release a
new version.
Thanks!
-- Mike
Mike Schilli
| Subject: | ldfr.patch |
diff -Naur Log-Dispatch-FileRotate-1.18/FileRotate.pm Log-Dispatch-FileRotate-1.18.patched/FileRotate.pm
--- Log-Dispatch-FileRotate-1.18/FileRotate.pm 2008-06-24 07:39:18.000000000 -0700
+++ Log-Dispatch-FileRotate-1.18.patched/FileRotate.pm 2008-10-08 12:36:52.000000000 -0700
@@ -31,6 +31,7 @@
$self->{'debug'} = 0;
$self->_basic_init(%p);
$self->{'LDF'} = Log::Dispatch::File->new(%p); # Our log
+ $self->{'timer'} = sub { time() } unless defined $self->{'timer'};
# Keep a copy of interesting stuff as well
$self->{params} = \%p;
@@ -199,7 +200,9 @@
my $size = (stat($fh))[7]; # Stat the handle to get real size
my $inode = (stat($fh))[1]; # get real inode
my $finode = (stat($name))[1]; # Stat the name for comparision
- warn localtime()." $$ s=$size, i=$inode, f=$finode, n=$name\n" if $self->{debug};
+ warn localtime()." $$ s=$size, i=$inode, f=".
+ (defined $finode ? $finode : "undef") .
+ ", n=$name\n" if $self->{debug};
# If finode and inode are the same then nobody has done a rename
# under us and we can continue. Otherwise just close and reopen.
@@ -333,7 +336,7 @@
# Check need for rotation. Loop through our recurrances looking
# for expiration times. Any we find that have expired we update.
- my $tm = time();
+ my $tm = $self->{timer}->();
my @recur = @{$self->{'recurrance'}};
@{$self->{'recurrance'}} = ();
for my $rec (@recur)
@@ -533,6 +536,15 @@
my $self = shift; # My object
my $pat = shift;
+ # (ms) Throw out expired occurances
+ my $now = $self->{timer}->();
+ if(defined $self->{'dates'}{$pat}) {
+ while( @{$self->{'dates'}{$pat}} ) {
+ last if $self->{'dates'}{$pat}->[0] >= $now;
+ shift @{$self->{'dates'}{$pat}};
+ }
+ }
+
# If this is first time then generate some new ones including one
# before our time to test against the log file
if(!defined $self->{'dates'}{$pat})
diff -Naur Log-Dispatch-FileRotate-1.18/test.pl Log-Dispatch-FileRotate-1.18.patched/test.pl
--- Log-Dispatch-FileRotate-1.18/test.pl 2008-06-24 19:14:03.000000000 -0700
+++ Log-Dispatch-FileRotate-1.18.patched/test.pl 2008-10-08 12:35:18.000000000 -0700
@@ -8,7 +8,7 @@
# Change 1..1 below to 1..last_test_to_print .
# (It may become useful if the test is moved to ./t subdirectory.)
-BEGIN { $| = 1; print "1..5\n"; }
+BEGIN { $| = 1; print "1..8\n"; }
END {print "not ok 1\n" unless $loaded;}
use Log::Log4perl;
use Log::Dispatch::FileRotate;
@@ -134,3 +134,46 @@
print "\n";
print "ok 5\n";
+### Reproduce no-activity bug
+
+our $count = 0;
+
+my $conf = q{
+log4perl.logger = INFO, default
+log4perl.appender.default = Log::Dispatch::FileRotate
+log4perl.appender.default.filename = test.log
+log4perl.appender.default.mode = append
+log4perl.appender.default.layout = SimpleLayout
+log4perl.appender.default.max = 6
+log4perl.appender.default.DatePattern = yyyy-MM-dd-HH
+};
+Log::Log4perl->init( \$conf );
+Log::Log4perl->appender_by_name("default")->{timer} =
+ sub { time() + $main::count * 3600 };
+# Log::Log4perl->appender_by_name("default")->{debug} = 1;
+
+unlink $_ for <test.log*>;
+
+Log::Log4perl::get_logger("")->info( "count=$count" );
+$count += 10;
+Log::Log4perl::get_logger("")->info( "count=$count" );
+Log::Log4perl::get_logger("")->info( "count=$count" );
+Log::Log4perl::get_logger("")->info( "count=$count" );
+
+if(! -f "test.log") {
+ print "not ";
+}
+print "ok 6\n";
+
+if(! -f "test.log.1") {
+ print "not ";
+}
+print "ok 7\n";
+
+ # This shouldn't exist
+if(-f "test.log.2") {
+ print "not ";
+}
+print "ok 8\n";
+
+unlink $_ for <test.log*>;