multiple processes break rotation (win32?) [rt.cpan.org #44524]

[mschout]

https://rt.cpan.org/Ticket/Display.html?id=44524

Hello,

I've encountered a problem with Log::Dispatch::FileRotate when running
multiple processes sharing the same log. My script to reproduce are
below. The script simply log the date every second and rotate every 5
seconds (this issue exists for daily rotation, too, which is how I first
noticed it). It works fine if you run a single process, but then as soon
as a launch another "nolog.pl" instance the existing logfiles are
deleted except for the one with the largest number, and no more rotation
happens.

This issue exists on win xp and server 2003, activeperl 5.8.8, log4perl
1.15, FileRotate.pm version 1.15, and also FileRotate.pm version 1.19.
The issue DOES NOT exist on linux (debian etch) perl 5.8.8, log4perl
1.07, FileRotate.pm 1.19.

Any help you can provide in resolving this would be greatly appreciated.
-Peter

#! /usr/bin/perl -w
# nolog.pl

use strict;
use warnings;
use Log::Log4perl qw(:levels get_logger);

Log::Log4perl->init_and_watch('log4perl.conf', 30);
my $log = get_logger('root');
$log->info("init");

while (1) {
    $log->info(gmtime);
    sleep(1);
}

$log->info("never here");

# log4perl.conf
log4perl.logger.root = TRACE,log1,console

# output to stderr
log4perl.appender.console = Log::Log4perl::Appender::Screen
log4perl.appender.console.stderr = 1
log4perl.appender.console.layout = Log::Log4perl::Layout::PatternLayout
log4perl.appender.console.layout.ConversionPattern = %d %c - %p - %m%n
log4perl.appender.console.Threshold = INFO

# output to log file
log4perl.appender.log1 = Log::Dispatch::FileRotate
log4perl.appender.log1.filename = logs/log1.txt
log4perl.appender.log1.mode = append
log4perl.appender.log1.min_level = info
log4perl.appender.log1.max = 5
log4perl.appender.log1.DatePattern = 0:0:0:0:0:0:5
log4perl.appender.log1.TZ = EDT
log4perl.appender.log1.layout = Log::Log4perl::Layout::PatternLayout
log4perl.appender.log1.layout.ConversionPattern = %d %c - %p - %m%n

[mschout]

Sounds like a locking issue. I don't test under M$, prefer *nix and
MacOSX.

Would it be possible for you to run each process under the perl
debugger and trace what is happening?

I am happy to wade through the traces to see if I can find anything.

cheers

Mark Pfeiffer markpf@mlp-consulting.com.au (calvus pinguis imperium)

On 25/03/2009, at 3:29 AM, Peter McAlpine via RT wrote:

Tue Mar 24 12:29:00 2009: Request 44524 was acted upon. Transaction: Ticket created by prock Queue: Log-Dispatch-FileRotate Subject: multiple processes break rotation (win32?) Broken in: 1.15, 1.19 Severity: (no value) Owner: Nobody Requestors: peter@aoeu.ca Status: new Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=44524 >

Hello,

I've encountered a problem with Log::Dispatch::FileRotate when running multiple processes sharing the same log. My script to reproduce are below. The script simply log the date every second and rotate every 5 seconds (this issue exists for daily rotation, too, which is how I
first noticed it). It works fine if you run a single process, but then as
soon as a launch another "nolog.pl" instance the existing logfiles are deleted except for the one with the largest number, and no more
rotation happens.

This issue exists on win xp and server 2003, activeperl 5.8.8,
log4perl 1.15, FileRotate.pm version 1.15, and also FileRotate.pm version 1.19. The issue DOES NOT exist on linux (debian etch) perl 5.8.8, log4perl 1.07, FileRotate.pm 1.19.

Any help you can provide in resolving this would be greatly
appreciated. -Peter

! /usr/bin/perl -w

nolog.pl

use strict; use warnings; use Log::Log4perl qw(:levels get_logger);

Log::Log4perl->init_and_watch('log4perl.conf', 30); my $log = get_logger('root'); $log->info("init");

while (1) { $log->info(gmtime); sleep(1); }

$log->info("never here");

log4perl.conf

log4perl.logger.root = TRACE,log1,console

output to stderr

log4perl.appender.console = Log::Log4perl::Appender::Screen log4perl.appender.console.stderr = 1 log4perl.appender.console.layout =
Log::Log4perl::Layout::PatternLayout log4perl.appender.console.layout.ConversionPattern = %d %c - %p - %m%n log4perl.appender.console.Threshold = INFO

output to log file

log4perl.appender.log1 = Log::Dispatch::FileRotate log4perl.appender.log1.filename = logs/log1.txt log4perl.appender.log1.mode = append log4perl.appender.log1.min_level = info log4perl.appender.log1.max = 5 log4perl.appender.log1.DatePattern = 0:0:0:0:0:0:5 log4perl.appender.log1.TZ = EDT log4perl.appender.log1.layout = Log::Log4perl::Layout::PatternLayout log4perl.appender.log1.layout.ConversionPattern = %d %c - %p - %m%n

[mschout]

Hi.

I realize this ticket is ancient, but I've recently released several updates to Log::Dispatch::FileRotate, and one of the things that has been fixed is that the file locking code was badly broken and two processes could be inside the critical section at the same time. This resulted in multiple rotations happening when only one rotation should have been happening on all platforms (if multiple processes managed to enter the critical section at the same time).

If you are still using Log::Dispatch::FileRotate, I would be interested to know if you still see this issue on Windows as of version 1.30.

-- Regards, Michael Schout

[mschout]

I ran the test script under strawberry 5.24.0 using two processes and the problem still exists, so disregard previous email. -- Regards, Michael Schout

[augusto-f-fonseca-alpt]

Hi, this situation persists even with version v5.32.1. I made a test with 10 processes and other with 10 threads. With 10 processes if i restart, rotation occurs. But when i use threads the rotation never occurs. I made a simple test: 1- Multiple Threads:

use strict;
use warnings;
use Log::Log4perl;
use Thread;

my $confString = q(
    log4perl.rootLogger                                               = DEBUG
    log4perl.logger.test_threads_logger                               = DEBUG, test_threads_appender
    log4perl.appender.test_threads_appender                           = Log::Dispatch::FileRotate
    log4perl.appender.test_threads_appender.filename                  = test_threads.log
    log4perl.appender.test_threads_appender.mode                      = append
    log4perl.appender.test_threads_appender.autoflush                 = 1
    log4perl.appender.test_threads_appender.size                      = 524288
    log4perl.appender.test_threads_appender.max                       = 3
    log4perl.appender.test_threads_appender.layout                    = Log::Log4perl::Layout::PatternLayout
    log4perl.appender.test_threads_appender.layout.ConversionPattern  = %d{yyyy-MM-dd HH:mm:ss} %-5p - %m%n
);
Log::Log4perl::init(\$confString);
my $logger = Log::Log4perl->get_logger("test_threads_logger");

my @list = ("p1", "p2", "p3", "p4", "p5", "p6", "p7", "p8", "p9", "p10");
my @threadlist = ();

for my $lst (@list) {
    my $t = Thread->new(\&thread_exec , $lst);
    print "Wating for thread for $lst\n";
    push @threadlist, $t;
}

for my $thd (@threadlist) {
    print "Wating for thread to join\n";
    $thd->join;
}

sub thread_exec {
    my $str = shift;
    while(1){
        $logger->info($str);
        sleep(1);
    }
}

2- Multiple processes:

use strict;
use warnings;
use Thread;

my @list = ("perl auxScript/test.pl p1", "perl auxScript/test.pl p2", "perl auxScript/test.pl p3", "perl auxScript/test.pl p4", "perl auxScript/test.pl p5", "perl auxScript/test.pl p6", "perl auxScript/test.pl p7", "perl auxScript/test.pl p8", "perl auxScript/test.pl p9", "perl auxScript/test.pl p10");
my @threadlist = ();

for my $lst (@list) {
  my $t = Thread->new(\&thread_exec , $lst);
  print "Wating for thread for $lst\n";
  push @threadlist, $t;
}

for my $thd (@threadlist) {
  print "Wating for thread to join\n";
  $thd->join;
}

sub thread_exec {
  my $cmd = shift;
  system($cmd);
}

Where test.pl:

use strict;
use warnings;
use Log::Log4perl;

my $arg1 = $ARGV[0];

my $confString = q(
    log4perl.rootLogger                                               = DEBUG
    log4perl.logger.test_logger                                       = DEBUG, test_appender
    log4perl.appender.test_appender                                   = Log::Dispatch::FileRotate
    log4perl.appender.test_appender.filename                          = test_processes.log
    log4perl.appender.test_appender.mode                              = append
    log4perl.appender.test_appender.autoflush                         = 1
    log4perl.appender.test_appender.size                              = 524288
    log4perl.appender.test_appender.max                               = 3
    log4perl.appender.test_appender.layout                            = Log::Log4perl::Layout::PatternLayout
    log4perl.appender.test_appender.layout.ConversionPattern          = %d{yyyy-MM-dd HH:mm:ss} %-5p - %m%n
);

Log::Log4perl::init(\$confString);

my $logger = Log::Log4perl->get_logger("test_logger");
while(1){
    $logger->info($arg1);
    sleep(1);
}

[augusto-f-fonseca-alpt]

Further testing on thread mode i see that the file is locked, on rotation gives: And if i try to do a move on console i have the error that other process is using the file.

[augusto-f-fonseca-alpt]

Further investigation, the condition "Log::Log4perl::init(\$confString);" locks the main file And that invokes the new() on "Log::Dispatch::File" And the lock exist's on:

$self->_open_file()
            unless $self->{close_after_write} || $self->{lazy_open};

This lock dont seems to be released, on destroy before rotation :(

[mschout]

Hi @augusto-f-fonseca-alpt thanks for the investigation.

FWIW, these days I'd strongly encourage use of one of the other "date based" rotation modules that do not require locking such as Log::Dispatch::File::Stamped

[augusto-f-fonseca-alpt]

Hi, thanks for the sugestion, but i dont use stamped rotations.