Skip to content

Commit

Permalink
Item12950: Use a different log rotate strategy
Browse files Browse the repository at this point in the history 
Copying the file contents just takes too long.  Rename the file.

Also removed the code for flock unlock.  It's recommended to let the
close do the unlock, so that any buffers written during the close don't
happen after the lock has been released.

git-svn-id: http://svn.foswiki.org/trunk@17792 0b4bb1d4-4e5a-0410-9cc4-b2b747904278
  • Loading branch information
GeorgeClark authored and GeorgeClark committed Jun 28, 2014
1 parent f92b1d4 commit 96ed613
Show file tree
Hide file tree
Showing 2 changed files with 66 additions and 157 deletions.
79 changes: 47 additions & 32 deletions UnitTestContrib/test/unit/LoggerTests.pm
View file
Expand Up @@ -787,26 +787,36 @@ sub PlainFileTestTime {
sub test_PlainFileEachEventSinceOnSeveralLogs {
my $this = shift;
my $logger = Foswiki::Logger::PlainFile->new();
my $cache = \&Foswiki::Logger::PlainFile::_time;
no warnings 'redefine';
*Foswiki::Logger::PlainFile::_time = \&PlainFileTestTime;
use warnings 'redefine';

# Write out the logfiles manually. Log rotate code doesn't handle
# the contrived dates well.

$plainFileTestTime = 3600;
$logger->log( 'info', "Seal" );
open( my $lf, '>', "$logDir/events.197001" ) or die "open failed";
print $lf '| '
. Foswiki::Time::formatTime( $plainFileTestTime, 'iso', 'gmtime' )
. " info | Seal |\n";
close $lf;
my $firstTime = time - 2 * 32 * 24 * 60 * 60;
$plainFileTestTime = $firstTime; # 2 months ago
$logger->log( 'info', "Dolphin" );
open( $lf, '>', "$logDir/events.201404" ) or die "open failed";
print $lf '| '
. Foswiki::Time::formatTime( $plainFileTestTime, 'iso', 'gmtime' )
. " info | Dolphin |\n";
close $lf;
$plainFileTestTime += 32 * 24 * 60 * 60; # 1 month ago
$logger->log( 'info', "Whale" );
$plainFileTestTime = time; # today
$logger->log( 'info', "Porpoise" );
open( $lf, '>', "$logDir/events.201405" ) or die "open failed";
print $lf '| '
. Foswiki::Time::formatTime( $plainFileTestTime, 'iso', 'gmtime' )
. " info | Whale |\n";
close $lf;
open( $lf, '>', "$logDir/events.log" ) or die "open failed";
my $now = time();
print $lf '| '
. Foswiki::Time::formatTime( $now, 'iso', 'gmtime' )
. " info | Porpoise |\n";
close $lf;

no warnings 'redefine';
*Foswiki::Logger::PlainFile::_time = $cache;
use warnings 'redefine';

#print STDERR "Calling eachEventSince info\n";
my $it = $logger->eachEventSince( 0, 'info' );
my $data;
$this->assert( $it->hasNext() );
Expand All @@ -822,7 +832,7 @@ sub test_PlainFileEachEventSinceOnSeveralLogs {
$this->assert_str_equals( "Whale", $data->[1] );
$this->assert( $it->hasNext() );
$data = $it->next();
$this->assert_equals( $plainFileTestTime, $data->[0] );
$this->assert_equals( $now, $data->[0] );
$this->assert_str_equals( "Porpoise", $data->[1] );
$this->assert( !$it->hasNext() );

Expand All @@ -837,7 +847,7 @@ sub test_PlainFileEachEventSinceOnSeveralLogs {
$this->assert_str_equals( "Whale", $data->[1] );
$this->assert( $it->hasNext() );
$data = $it->next();
$this->assert_equals( $plainFileTestTime, $data->[0] );
$this->assert_equals( $now, $data->[0] );
$this->assert_str_equals( "Porpoise", $data->[1] );
$this->assert( !$it->hasNext() );

Expand Down Expand Up @@ -1021,33 +1031,38 @@ sub verify_logAndReplayUnicode {
my $this = shift;
my $bytestr = "lower delta as a string: \xce\xb4";
my $unicode = "lower delta as a string: \x{3b4}";
print STDERR "Attempting to log bytestring\n";

#print STDERR "Attempting to log bytestring\n";
$this->{logger}->log( 'info', 'info', $bytestr );
print STDERR "Attempting to log unicode \n";

#print STDERR "Attempting to log unicode \n";
$this->{logger}->log( 'info', 'info', $unicode );
print "Logged Data (bytestr) "
. ( ( utf8::is_utf8($bytestr) ) ? "is" : "is not" )
. " UTF8\n";
print "Logged Data (unicode) "
. ( ( utf8::is_utf8($unicode) ) ? "is" : "is not" )
. " UTF8\n";

#print "Logged Data (bytestr) "
# . ( ( utf8::is_utf8($bytestr) ) ? "is" : "is not" )
# . " UTF8\n";
#print "Logged Data (unicode) "
# . ( ( utf8::is_utf8($unicode) ) ? "is" : "is not" )
# . " UTF8\n";

my $it = $this->{logger}->eachEventSince( 0, 'info' );
my $data;
$this->assert( $it->hasNext() );
$data = $it->next();
$this->assert_str_equals( $bytestr, $data->[2],
'byte string is corrupted' );
print "Returned Data (bytestr) "
. ( ( utf8::is_utf8( $data->[2] ) ) ? "is" : "is not" )
. " UTF8\n";
print STDERR "$data->[2]\n";

#print "Returned Data (bytestr) "
# . ( ( utf8::is_utf8( $data->[2] ) ) ? "is" : "is not" )
# . " UTF8\n";
#print STDERR "$data->[2]\n";
$this->assert( $it->hasNext() );
$data = $it->next();
print "Returned Data (unicode) "
. ( ( utf8::is_utf8( $data->[2] ) ) ? "is" : "is not" )
. " UTF8\n";
print STDERR "$data->[2]\n";

#print "Returned Data (unicode) "
# . ( ( utf8::is_utf8( $data->[2] ) ) ? "is" : "is not" )
# . " UTF8\n";
#print STDERR "$data->[2]\n";
$this->assert_str_equals( $bytestr, $data->[2],
'unicode string is corrupted' );
$this->assert( !$it->hasNext() );
Expand Down
144 changes: 19 additions & 125 deletions core/lib/Foswiki/Logger/PlainFile.pm
View file
Expand Up @@ -114,9 +114,9 @@ sub log {
( $level, @fields ) = @_;
}

my $now = _time();
my @logs = _getLogsForLevel( [$level] );
my $log = shift @logs;
my $now = _time();
_rotate( $LEVEL2LOG{$level}, $log, $now );
my $time = Foswiki::Time::formatTime( $now, 'iso', 'gmtime' );

Expand Down Expand Up @@ -145,7 +145,6 @@ sub log {
binmode $file, ":encoding(utf-8)";
_lock($file);
print $file "$message\n";
_unlock($file);
close($file);
}
elsif ( $Foswiki::cfg{isVALID} ) {
Expand Down Expand Up @@ -173,12 +172,6 @@ sub _lock { # borrowed from Log::Dispatch::FileRotate, Thanks!
return 1;
}

sub _unlock { # borrowed from Log::Dispatch::FileRotate, Thanks!
my $fh = shift;
eval { flock( $fh, LOCK_UN ) };
return 1;
}

=begin TML
---++ ObjectMethod eachEventSince($time, \@levels, $version) -> $iterator
Expand Down Expand Up @@ -206,6 +199,9 @@ sub eachEventSince {
my $logYear = Foswiki::Time::formatTime( $time, '$year', 'servertime' );
my $logMonth = Foswiki::Time::formatTime( $time, '$mo', 'servertime' );

print STDERR "Scanning $logYear:$logMonth thru $nowLogYear:$nowLogMonth\n"
if (TRACE);

# Convert the requested level into a regular expression for the scan
my $reqLevel = join( '|', @$level );
$reqLevel = "(?:$reqLevel)";
Expand Down Expand Up @@ -333,131 +329,29 @@ sub _rotate {
print STDERR "compare $modMonth, $curMonth\n" if (TRACE);
return if ( $modMonth == $curMonth );

# The log was last modified in a month that was not the current month.
# Rotate older entries out into month-by-month logfiles.

# Open the current log
my $lf;
unless ( open( $lf, '<', $log ) ) {
print STDERR
"ERROR: PlainFile Logger could not open logfile $log for read: $! \n";
my $lockfile;
unless ( open( $lockfile, '>', $log . 'LOCK' ) ) {
print STDERR "ERROR: PlainFile Logger could not open $log.LOCK: $! \n";
return;
}
flock( $lockfile, LOCK_EX );

my %months;

local $/ = "\n";
my $line;
my $linecount;
my $stashline = '';
while ( $line = <$lf> ) {
$stashline .= $line;
my @event = split( /\s*\|\s*/, $line );
$linecount++;
if ( scalar(@event) > 7 ) {
print STDERR "Bad log "
. join( ' | ', @event )
. " | - Skipped \n "
if (TRACE);
$stashline = '';
next;
}

unless ( $event[1] ) {
print STDERR
"BAD LOGFILE LINE - skip $line - line $linecount in $log\n"
if (TRACE);
next;
}

#Item12022: parseTime bogs the CPU down here, so try a dumb regex first
# (assuming ISO8601 format Eg. 2000-01-31T23:59:00Z). Result: 4x speedup
my $eventMonth;
if ( $event[1] =~ /^(\d{4})-(\d{2})-\d{2}T[0-9:]+Z\b/ ) {
$eventMonth = $1 . $2;
}
else {
print STDERR ">> Non-ISO date string encountered\n" if (TRACE);
my $tempMonth = Foswiki::Time::parseTime( $event[1] );
unless ( defined $tempMonth ) {
print STDERR
">> BAD LOGFILE LINE - skip $line - line $linecount in $log\n"
if (TRACE);
next;
}
$eventMonth = _time2month($tempMonth);
}

if ( !defined $eventMonth ) {
my $newname = $log;
$newname =~ s/log$/$modMonth/;
print STDERR "Renaming from $log to $newname \n" if (TRACE);

print STDERR
">> Bad time in log - skip: $line - line $linecount in $log\n"
if (TRACE);
next;
}

if ( $eventMonth < $curMonth ) {
push( @{ $months{$eventMonth} }, $stashline );
$stashline = '';
}
else {

# Reached the start of log entries for this month
print STDERR ">> Reached start of this month - count $linecount \n"
if (TRACE);
last;
}
}
print STDERR " Months "
. join( ' ', keys %months )
. " - processed $linecount records \n"
if (TRACE);

if ( !scalar( keys %months ) ) {

# no old months, we're done. The modify time on the current
# log will be touched by the next write, so we won't attempt
# to rotate again until next month.
print STDERR ">> No old months\n" if (TRACE);
unless ( -e $newname ) {
open( my $lf, '>>', $log );
_lock($lf);
rename $log, $newname;
close($lf);
return;
unlink $log . 'LOCK';
}

# Sook up the rest of the current log
$line ||= '';
$/ = undef;
my $remainingLog = <$lf>;
close($lf);

my $curLog = $line;
$curLog .= $remainingLog if defined $remainingLog;

foreach my $month ( keys %months ) {
my $bf;
my $backup = $log;
$backup =~ s/log$/$month/;
if ( -e $backup ) {
print STDERR
"ERROR: PlainFile Logger could not create $backup - file exists\n";
return;
}
unless ( open( $bf, '>', $backup ) ) {
print STDERR
"ERROR: PlainFile Logger could not create $backup - $! \n";
return;
}
print $bf join( '', @{ $months{$month} } );
close($bf);
else {
print STDERR "ROTATE SKIPPED - prior log ($log) exists\n";
unlink $log . 'LOCK';
}

# Finally rewrite the shortened current log
unless ( open( $lf, '>', $log ) ) {
print STDERR
"ERROR: PlainFile Logger could not open logfile $log for write: $! \n";
return;
}
print $lf $curLog;
close($lf);
}

1;
Expand Down

0 comments on commit 96ed613

Please sign in to comment.