Bug #44524 for Log-Dispatch-FileRotate: multiple processes break rotation (win32?)

Tue Mar 24 12:29:00 2009 peter [...] aoeu.ca - Ticket created

Subject:

multiple processes break rotation (win32?)

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

Tue Mar 24 21:29:03 2009 markpf [...] mlp-consulting.com.au - Correspondence added

CC:	"Mark Pfeiffer" <markpf [...] mlp-consulting.com.au>
Subject:	Re: [rt.cpan.org #44524] multiple processes break rotation (win32?)
Date:	Wed, 25 Mar 2009 12:28:30 +1100
To:	bug-Log-Dispatch-FileRotate [...] rt.cpan.org
From:	"Mark Pfeiffer" <markpf [...] mlp-consulting.com.au>

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: Show quoted text

> 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

Tue Mar 24 21:29:04 2009 The RT System itself - Status changed from 'new' to 'open'

Thu Mar 26 15:30:38 2009 peter [...] aoeu.ca - Correspondence added

Subject:	Re: [rt.cpan.org #44524] multiple processes break rotation (win32?)
Date:	Thu, 26 Mar 2009 15:27:47 -0400
To:	bug-Log-Dispatch-FileRotate [...] rt.cpan.org
From:	Peter McAlpine <peter [...] aoeu.ca>

Message body is not shown because sender requested not to inline it.

Hello, This issue is/was two-fold: 1. Windows prevents you from deleting an open file. So if a second process has the LDF open it the rename call fails. This is what was causing the initial issue. 2. NTFS does not have inodes (per se), thus preventing detection of the log files being rotated by another process. The only way I could think of resolving #1 was to close/reopen the file each time we're in log_message. If there's a better way I'm all ears. I tested a heavily logged application with large files and didn't notice a significant performance hit. In windows a file can be uniquely identified by combining the file (high and low) index and volume serial number, all of which can be gotten via a kernel32 call to GetFileInformationByHandle. This is used as an inode substitute to detect log rotation by another process (thus resolving #2). I've tested on *nix and didn't notice any change in behaviour (outside of the debug logging added to report rename failures). On windows the performance is significantly worse (10000 log iterations went from 6 seconds to 26 seconds in my rudimentary tests, or roughly 2.6ms per message). This is completely because the log is being closed and reopened each iteration (commenting these two lines out speeds it back up). Unfortunately, beyond implementing a master log service (emulating syslogd) I don't see a way to resolve this. Logging larger messages and increasing the log file size being written to (up to 1.2G) did not significantly affect this performance which again leads me to believe the bulk of the performance degradation is due to the closing and opening the file. I'm going to give it a try with my application and see if I notice the degraded performance. I think I need this working correctly rather than quickly. My diff is attached. -Peter On Tue, Mar 24, 2009 at 9:29 PM, Mark Pfeiffer via RT < bug-Log-Dispatch-FileRotate@rt.cpan.org> wrote: Show quoted text

> <URL: http://rt.cpan.org/Ticket/Display.html?id=44524 > > > 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

> > > >

Tue Apr 07 14:41:12 2009 peter [...] aoeu.ca - Correspondence added

Subject:	Re: [rt.cpan.org #44524] multiple processes break rotation (win32?)
Date:	Tue, 7 Apr 2009 14:40:34 -0400
To:	bug-Log-Dispatch-FileRotate [...] rt.cpan.org
From:	Peter McAlpine <peter [...] aoeu.ca>

Message body is not shown because sender requested not to inline it.

Hello, Please find an updated version of FileRotate.pm. This fixes some other issues I've noticed: - Multiple processes would not necessarily be on the same schedule for rotations (due to using a different base for Date::Manip::ParseRecur) - A rotation would happen every time my a process initialized Log4Perl/FileRotate. Hopefully these changes can be considered useful, but I have not taken the time to test this new version on Linux or with any system other than the one I am using. Thanks again for your work in creating this very useful perl library. -Peter On Thu, Mar 26, 2009 at 3:27 PM, Peter McAlpine <peter@aoeu.ca> wrote: Show quoted text

> Hello, > > This issue is/was two-fold: > > 1. Windows prevents you from deleting an open file. So if a second > process has the LDF open it the rename call fails. This is what was causing > the initial issue. > 2. NTFS does not have inodes (per se), thus preventing detection of the > log files being rotated by another process. > > The only way I could think of resolving #1 was to close/reopen the file > each time we're in log_message. If there's a better way I'm all ears. I > tested a heavily logged application with large files and didn't notice a > significant performance hit. > > In windows a file can be uniquely identified by combining the file (high > and low) index and volume serial number, all of which can be gotten via a > kernel32 call to GetFileInformationByHandle. This is used as an inode > substitute to detect log rotation by another process (thus resolving #2). > > I've tested on *nix and didn't notice any change in behaviour (outside of > the debug logging added to report rename failures). > > On windows the performance is significantly worse (10000 log iterations > went from 6 seconds to 26 seconds in my rudimentary tests, or roughly 2.6ms > per message). This is completely because the log is being closed and > reopened each iteration (commenting these two lines out speeds it back up). > Unfortunately, beyond implementing a master log service (emulating syslogd) > I don't see a way to resolve this. > > Logging larger messages and increasing the log file size being written to > (up to 1.2G) did not significantly affect this performance which again leads > me to believe the bulk of the performance degradation is due to the closing > and opening the file. > > I'm going to give it a try with my application and see if I notice the > degraded performance. I think I need this working correctly rather than > quickly. > > My diff is attached. > > -Peter > > > On Tue, Mar 24, 2009 at 9:29 PM, Mark Pfeiffer via RT < > bug-Log-Dispatch-FileRotate@rt.cpan.org> wrote: >

>> <URL: http://rt.cpan.org/Ticket/Display.html?id=44524 > >> >> 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

>> >> >> >>

Sat Aug 05 13:13:37 2017 MSCHOUT [...] cpan.org - Correspondence added

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

Sat Aug 05 13:25:16 2017 MSCHOUT [...] cpan.org - Correspondence added

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

Wed Feb 07 10:07:31 2018 MSCHOUT [...] cpan.org - Correspondence added

Issue migrated to github: https://github.com/mschout/perl-log-dispatch-filerotate/issues/17 -- Regards, Michael Schout

Wed Feb 07 10:07:31 2018 MSCHOUT [...] cpan.org - Status changed from 'open' to 'resolved'