log4perl-devel

[log4perl-devel] Bug in Log::Log4perl::Appender::File v0.33

[James F. <jf...@ma...>]

When v0.33 came out, I switched over my file-based loggers from 
Log::Dispatch::File to Log::Log4perl::Appender::File.

The configuration I'm using looks like this when dumped as a hashref:

0  HASH(0x9adcf4)
    'log4perl.appender.dpa00102' => 'Log::Log4perl::Appender::File'
    'log4perl.appender.dpa00102.Threshold' => 'INFO'
    'log4perl.appender.dpa00102.filename' => 'dpa00102.log'
    'log4perl.appender.dpa00102.layout' => 
'Sys3D::Logger::Layout::Common'
    'log4perl.appender.dpa00102_debug' => 'Log::Log4perl::Appender::File'
    'log4perl.appender.dpa00102_debug.filename' => 'dpa00102_debug.log'
    'log4perl.appender.dpa00102_debug.layout' => 
'Sys3D::Logger::Layout::Common'
    'log4perl.appender.dpa00102_debug.layout.ConversionPattern' => 
'debug'
    'log4perl.logger' => 'DEBUG, dpa00102_debug, dpa00102'

When I started using this configuration, I noticed that all of my log 
messages started going to the same file.  Each logging statement was 
logged twice in this case, though each had it's own proper format (the 
custom layout module referenced above is just a subclass of 
PatternLayout):

06/07/2003 10:53:24 INFO  dpa00102.pl[22997/th0] START
06/07/2003 10:53:24.584 INFO  dpa00102.pl[22997/th0] (main::): START 
(dpa00102.pl/11)

The problem is that Log::Log4perl::Appender::File always open the same 
filehandle 'FH', so a logging configuration that has two instances of 
the appender end up sending all messages to the file referenced by the 
last instance to be created.

If I load up the above config and then dump 
%Log::Log4perl::Logger::APPENDER_BY_NAME, you can see how the glob is 
re-used:

0  HASH(0x7c69cc)
    'dpa00102' => Log::Log4perl::Appender=HASH(0xe66ff0)
       'appender' => Log::Log4perl::Appender::File=HASH(0xe671b8)
          'Threshold' => 'INFO'
          'autoflush' => 1
          'fh' => GLOB(0xe617a0)
             -> *Log::Log4perl::Appender::File::FH
                   FileHandle({*Log::Log4perl::Appender::File::FH}) => 
fileno(7)
          'filename' => 'dpa00102.log'
          'min_level' => 'debug'
          'mode' => 'append'
          'name' => 'dpa00102'
       'layout' => Sys3D::Logger::Layout::Common=HASH(0xe67188)
          'CSPECS' => 'cCdFHIlLmMnpPrtxX%'
          'dontCollapseArrayRefs' => undef
          'format' => undef
          'info_needed' => HASH(0xe60294)
          [...]
          'message_chompable' => 1
          'printformat' => '%s %-5s %s[%s/th%s] %s%s'
          'stack' => ARRAY(0xe67158)
             0  ARRAY(0xe6729c)
                0  'd'
                [...]
       'level' => 20000
       'name' => 'dpa00102'
       'warp_message' => undef
    'dpa00102_debug' => Log::Log4perl::Appender=HASH(0xe51740)
       'appender' => Log::Log4perl::Appender::File=HASH(0xe5177c)
          'autoflush' => 1
          'fh' => GLOB(0xe617a0)
             -> REUSED_ADDRESS
          'filename' => 'dpa00102_debug.log'
          'min_level' => 'debug'
          'mode' => 'append'
          'name' => 'dpa00102_debug'
       'layout' => Sys3D::Logger::Layout::Common=HASH(0xe5fb7c)
          'CSPECS' => 'cCdFHIlLmMnpPrtxX%'
          'dontCollapseArrayRefs' => undef
          'format' => undef
          'info_needed' => HASH(0xe517e8)
          [...]
          'message_chompable' => 0
          'printformat' => '%s %-5s %s[%s/th%s] %s(%s): %s (%s/%s)%s'
          'stack' => ARRAY(0xe517a0)
             0  ARRAY(0xe602d0)
                0  'd'
                [...]
       'level' => 10000
       'name' => 'dpa00102_debug'
       'warp_message' => undef

The solution is to make sure that a new glob is used each time, which 
can be done in a number of ways, though Symbol::geniosym probably makes 
the most sense.  Changing the code that opens the file to this:

      require Symbol;
      my $fh = Symbol::geniosym;
      open $fh, "$arrows$self->{filename}" or
          die "Can't open $self->{filename} ($@)";

I've tested this and the problem described above does go away with this 
approach.

Regards.

--
j.

Re: [log4perl-devel] Bug in Log::Log4perl::Appender::File v0.33

[Mike S. <log...@pe...>]

On Sat, 7 Jun 2003, James FitzGibbon wrote:

> When v0.33 came out, I switched over my file-based loggers from
> Log::Dispatch::File to Log::Log4perl::Appender::File.
> ...
> The problem is that Log::Log4perl::Appender::File always open the same
> filehandle 'FH', so a logging configuration that has two instances of
> the appender end up sending all messages to the file referenced by the
> last instance to be created.

Ouch. Thanks for reporting that. Here's a patch (I stole the 'local'-trick
from Log::Dispatch::File), we should push a new release soon:

Index: Changes
===================================================================
RCS file: /cvsroot/log4perl/Log-Log4perl/Changes,v
retrieving revision 1.127
diff -a -u -r1.127 Changes
--- Changes	31 May 2003 18:18:54 -0000	1.127
+++ Changes	7 Jun 2003 18:55:22 -0000
@@ -2,8 +2,13 @@
 Revision history for Log::Log4perl
 ##################################################

+0.34 (not yet released)
+    * (ms) James FitzGibbon <jam...@ta...> noticed a major
+           bug in Log::Log4perl::Appender::File and sent a patch. Problem
+           was that it was reusing the same file handle for every opened file,
+           so all messages were ending up in the same file.

-0.33
+0.33 05/30/2003
     * (kg) CPAN rt#2636, coordinating XML::DOM version required across modules
            and unit tests
     * (ms) Removed Log::Dispatch dependency, added standard
Index: lib/Log/Log4perl/Appender/File.pm
===================================================================
RCS file: /cvsroot/log4perl/Log-Log4perl/lib/Log/Log4perl/Appender/File.pm,v
retrieving revision 1.1
diff -a -u -r1.1 File.pm
--- lib/Log/Log4perl/Appender/File.pm	29 May 2003 08:37:11 -0000	1.1
+++ lib/Log/Log4perl/Appender/File.pm	7 Jun 2003 18:55:22 -0000
@@ -26,10 +26,12 @@
         $arrows = ">>";
     }

-    open FH, "$arrows$self->{filename}" or
+    my $fh = do { local *FH; *FH; };
+
+    open $fh, "$arrows$self->{filename}" or
         die "Can't open $self->{filename} ($@)";

-    $self->{fh} = \*FH;
+    $self->{fh} = $fh;

     bless $self, $class;
 }
Index: t/026FileApp.t
===================================================================
RCS file: /cvsroot/log4perl/Log-Log4perl/t/026FileApp.t,v
retrieving revision 1.4
diff -a -u -r1.4 026FileApp.t
--- t/026FileApp.t	31 May 2003 18:51:29 -0000	1.4
+++ t/026FileApp.t	7 Jun 2003 18:55:23 -0000
@@ -25,9 +25,9 @@
     mkdir("$WORK_DIR", 0755) || die "can't create $WORK_DIR ($!)";
 }

-my $testfile = File::Spec->catfile(qw(t tmp test26.log));
+my $testfile = File::Spec->catfile($WORK_DIR, "test26.log");

-BEGIN {plan tests => 5}
+BEGIN {plan tests => 6}

 END { unlink $testfile;
       unlink "${testfile}_1";
@@ -126,7 +126,7 @@
     $log->info("Shu-wa-chi!");

     for(qw(1 2)) {
-        open FILE, "<${testfile}_$_" or die "Cannot create ${testfile}_$_";
+        open FILE, "<${testfile}_$_" or die "Cannot open ${testfile}_$_";
         $content = join '', <FILE>;
         close FILE;

@@ -137,4 +137,34 @@
     # We don't have Log::Dispatch, skip these cases
     ok(1);
     ok(1);
+}
+
+#########################################################
+# Check if the 0.33 Log::Log4perl::Appender::File bug is
+# fixed which caused all messages to end up in the same
+# file.
+#########################################################
+$data = <<EOT;
+log4perl.category = INFO, FileAppndr1, FileAppndr2
+log4perl.appender.FileAppndr1          = Log::Log4perl::Appender::File
+log4perl.appender.FileAppndr1.filename = ${testfile}_1
+log4perl.appender.FileAppndr1.mode     = append
+log4perl.appender.FileAppndr1.layout   = Log::Log4perl::Layout::SimpleLayout
+
+log4perl.appender.FileAppndr2          = Log::Log4perl::Appender::File
+log4perl.appender.FileAppndr2.filename = ${testfile}_2
+log4perl.appender.FileAppndr2.mode     = append
+log4perl.appender.FileAppndr2.layout   = Log::Log4perl::Layout::SimpleLayout
+EOT
+
+Log::Log4perl::init(\$data);
+$log = Log::Log4perl::get_logger("");
+$log->info("Shu-wa-chi!");
+
+for(qw(1 2)) {
+    open FILE, "<${testfile}_$_" or die "Cannot open ${testfile}_$_";
+    $content = join '', <FILE>;
+    close FILE;
+
+    ok($content, "INFO - Shu-wa-chi!\n");
 }

-- Mike

Mike Schilli
log...@pe...
http://perlmeister.com
http://log4perl.sourceforge.net