Possible scoping issue with Log::Log4perl logger

talexb has asked for the wisdom of the Perl Monks concerning the following question:

I hope this isn't a stupid question, but at least I've discovered the solution to my problem, and I'm happy to share this story in the event that it helps someone else.

I've developed a pile of scripts that use Log::Log4perl, a module that I love to bits. Wanting to implement a system that would E-Mail me when there was a problem, I decided to add an E-Mail appender to my configuration. It worked fine in my test scripts, but didn't work in my work scripts, and I couldn't understand why.

I finally figured it out this afternoon (which will explain why I'm pausing to sip from my tall can of Waterloo Amber "Ontario's First Craft Brewery"). My test script looks like this:

{
  Log::Log4perl->init ( $log4perl_config );
  my $log = Log::Log4perl->get_logger();
  ..
  $log->info('Some stuff');
}
[download]

This works fine. My work scripts are bigger and have subroutines in which I want to do logging, so they look like this:

my $log;
{
  Log::Log4perl->init ( $log4perl_config );
  $log = Log::Log4perl->get_logger();
  ..
  $log->info('Some stuff');
  do_something();
}
sub do_something
{
  $log->info('Some other stuff');
  ..
}
[download]

See the difference? I'm using what I call a file scoped variable in the work script so that I don't have to pass the logger into the subroutine (something MSCHILLI goes 'Brrrr!' to here). I believe Log::Log4perl collects log entries to go out by E-Mail until the logger goes out of scope.

So the test script works fine. The work script's logger (I thought) would also go out of scope and send the E-Mail when the script finishes -- but no E-Mail is sent. Why not?

Anyway, my workaround is going to be to call get_logger in whichever scope I need to do logging. This works fine, but I'm left wondering why doesn't Log::Log4perl see that the logger has gone out of scope in the work script and send the E-Mail? Is there a 'finalize' or 'terminate' method I could have called to trigger this? Is this an error in the behaviour? (I find that hard to believe, for a module that's been around since 2002).

Alex / talexb / Toronto

Thanks PJ. We owe you so much. Groklaw -- RIP -- 2003 to 2013.

Comment on Possible scoping issue with Log::Log4perl logger Select or Download Code

Replies are listed 'Best First'.
Re: Possible scoping issue with Log::Log4perl logger by trwww (Priest) on Jun 16, 2018 at 16:05 UTC
I've poked the Log::log4perl internals a bit before, but I don't have any of it memorized so this is mostly guesses but: Anyway, my workaround is going to be to call get_logger in whichever scope I need to do logging. Right, this is what you have to do here. Sounds like you understand why. but I'm left wondering why doesn't Log::Log4perl see that the logger has gone out of scope in the work script and send the E-Mail? For the same reason you can call `->get_logger` without specifying the config again and get the expected logger object. Even though its went out of scope in your block, the instance of your logging object still exists in log4perl, so its not went out of scope everywhere yet. If you read through the l4p FAQ and review the email and buffering parts, it might might help explain whats going on? #How-can-I-configure-Log::Log4perl-to-send-me-email-if-something-happens?	[reply] [d/l]
Re^2: Possible scoping issue with Log::Log4perl logger by talexb (Chancellor) on Jun 16, 2018 at 16:37 UTC
Thanks for the link to the documentation .. I guess I'm being thick, but it strikes me that the script ending would mean that the logger goes out of scope .. which should send the E-Mail. But I'm going to have to do some testing on that aspect of things. Appreciate the feedback. :) Alex / talexb / Toronto Thanks PJ. We owe you so much. Groklaw -- RIP -- 2003 to 2013.	[reply]
Re: Possible scoping issue with Log::Log4perl logger by choroba (Cardinal) on Jun 15, 2018 at 22:01 UTC
You don't show how the e-mail gets send. Note that global destruction (happening on program end) doesn't guarantee the order in which the objects are destroyed - maybe some information needed to send the e-mail is already missing? ($q=q:Sq=~/;[c](.)(.)/;chr(-\|\|-\|5+lengthSq)`"S\|oS2"`map{chr \|+ord }map{substrSq`S_+\|`\|}3E\|-\|`7**2-3:)=~y+S\|`+$1,++print+eval$q,q,a, [download]	[reply] [d/l]
Re^2: Possible scoping issue with Log::Log4perl logger by talexb (Chancellor) on Jun 15, 2018 at 22:18 UTC
Sorry -- I assume that this was pretty straightforward. here's the configuration file, edited for security .. 1 # Configuration file for work script 2 3 log4perl.logger = INFO, Screen, Logfile, Mailer 4 5 log4perl.appender.Screen = Log::Log4perl::Appender::Scree +n 6 log4perl.appender.Screen.stderr = 0 7 log4perl.appender.Screen.layout = Log::Log4perl::Layout::Pattern +Layout 8 log4perl.appender.Screen.layout.ConversionPattern = %d %p : %m%n 9 log4perl.appender.Screen.Threshold = INFO 10 11 log4perl.appender.Logfile = Log::Log4perl::Appender::File 12 log4perl.appender.Logfile.filename = work_script.log 13 log4perl.appender.Logfile.mode = append 14 log4perl.appender.Logfile.layout = Log::Log4perl::Layout::Patter +nLayout 15 log4perl.appender.Logfile.layout.ConversionPattern = %d %p : %m%n 16 17 log4perl.appender.Mailer = XYZ::LogDispatchEmailSender 18 log4perl.appender.Mailer.to = someguy@example.com 19 # 20 log4perl.appender.Mailer.subject = XYZ Topic 21 log4perl.appender.Mailer.layout = Log::Log4perl::Layout::PatternL +ayout 22 log4perl.appender.Mailer.layout.ConversionPattern = %d %p : %m%n 23 log4perl.appender.Mailer.Threshold = INFO [download] The module I use to actually send an E-Mail is here: 1 package XYZ::LogDispatchEmailSender; 2 3 # 2018-0515: From the MetaCPAN page 4 # https://metacpan.org/pod/Log::Dispatch::Email, here's a local m +odule that 5 # will send E-Mail. .. 6 # .. 7 8 use Log::Dispatch::Email; 9 10 use base qw( Log::Dispatch::Email ); 11 12 use Email::Simple; 13 use Email::Sender::Simple qw(sendmail); 14 use Email::Sender::Transport::SMTP qw(); 15 use Try::Tiny; 16 17 use lib ..; 18 19 use XYZEMail; 20 21 sub send_email 22 { 23 my $self = shift; 24 my %p = @_; 25 26 my $message = Email::Simple->create( 27 header => [ 28 To => join(', ',@{ $self->{'to'} }), 29 From => 'anotherguy@example.com', 30 Subject => $self->{'subject'}, 31 ], 32 body => $p{ message }, 33 ); 34 35 try { 36 sendmail( 37 $message, 38 { 39 from => 'anotherguy@example.com', 40 transport => Email::Sender::Transport::SMTP->new( 41 { 42 host => $XYZEMail::Host, 43 port => $XYZEMail::Port, 44 sasl_username => $XYZEMail::User, 45 sasl_password => $XYZEMail::Password, 46 ssl => 'starttls', 47 } 48 ) 49 } 50 ); 51 } 52 catch { 53 warn "sending failed: $_"; 54 }; 55 } 56 57 1; [download] Alex / talexb / Toronto Thanks PJ. We owe you so much. Groklaw -- RIP -- 2003 to 2013.	[reply] [d/l] [select]
Re: Possible scoping issue with Log::Log4perl logger ( END { undef $log; } ) by beech (Parson) on Jun 16, 2018 at 22:31 UTC
Hi I see things working as designed so far, as in the appender gets called #!/usr/bin/perl -- use strict; use warnings; use Log::Log4perl 1.49; my $logger ; sub bye { $logger->info("bye"); } { my $logconfig = <<'__LOGCONFIG__'; log4perl.rootLogger = ALL, First, Mailer log4perl.appender.First = Log::Log4perl::Appender::Screen log4perl.appender.First.layout = SimpleLayout log4perl.appender.Mailer = FakeMailSend log4perl.appender.Mailer.to = FakeMailSend@example.com log4perl.appender.Mailer.subject = FakeMailSend log4perl.appender.Mailer.layout = SimpleLayout # log4perl.appender.Mailer.buffered = 0 __LOGCONFIG__ Log::Log4perl::init( \$logconfig ); $logger = Log::Log4perl->get_logger; $logger->debug('debug'); $logger->info('info'); $logger->warn('warn'); $logger->error('error'); $logger->trace('trace'); $logger->fatal('fatal'); bye; } exit( 0 ); BEGIN { package FakeMailSend; use Log::Dispatch::Email::MailSend qw[]; use base qw( Log::Dispatch::Email::MailSend ); sub send_email { warn "@_\n"; } 1; } __END__ DEBUG - debug INFO - info WARN - warn ERROR - error TRACE - trace FATAL - fatal INFO - bye FakeMailSend=HASH(0xe33e14) message DEBUG - debug INFO - info WARN - warn ERROR - error TRACE - trace FATAL - fatal INFO - bye [download] But if I actually try sending the mail (rename my sub send_mail) `Can't locate object method "open" via package "Mail::Mailer::smtp" at +lib/Mail/Send.pm line 58 during global destruction.` [download] Without buffering its `Died at site/lib/Mail/Mailer.pm line 158.` for every attempt. An explicit `undef $logger ;` produces the same good result Adding `use Mail::Mailer::smtp();` produces the same failure to send the mail to example :) `No such file or directory at site/lib/Mail/Mailer.pm line 158 during global destruction.` as without buffering `No such file or directory at site/lib/Mail/Mailer.pm line 158.` Trying to `require Mail::Mailer::smtp;` from within send_email fails as before `Can't locate object method "open" via package "Mail::Mailer::smtp"` So, Mail::Mailer::smtp can't be loaded during global destruction. Does Email::... eventually use it? Not important :) So, if using a global for convenience, solution is `END { undef $logger ; }` [download]	[reply] [d/l] [select]
Re^2: Possible scoping issue with Log::Log4perl logger ( END { undef $log; } ) by talexb (Chancellor) on Jun 16, 2018 at 23:35 UTC
Thanks, the `undef $logger` solution occurred to me as I was running errands today .. but I'm still going to conduct some tests to see if I understand how scoping on a file variable works. I thought I understood, but apparently I have not yet reached enlightenment. :) Alex / talexb / Toronto Thanks PJ. We owe you so much. Groklaw -- RIP -- 2003 to 2013.	[reply] [d/l]

Back to Seekers of Perl Wisdom