[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.