log4perl run from within another package not firing messages sent through email

Question

I'm seeing behavior that I can't explain when using log4perl to send a message by email.

So the following test script works just fine and an email is sent without problems:

#!/usr/bin/perl
use strict;
use warnings;
use Log::Log4perl qw(:easy);
use Log::Dispatch;

my $appender_email = Log::Log4perl::Appender->new(
    "Log::Dispatch::Email::SSMTP",
    threshold => "INFO",
    to => 'myemail@mail.com',
    subject => 'Perl script message'
);

my $email_logger = get_logger();
$email_logger->level($INFO);
$email_logger->add_appender($appender_email);

$email_logger->info('hi');

The Log::Dispatch::Email::SSMTP is a module I wrote to send emails using the ssmtp command.

The weirdness begins when this same exact code is moved to another package in another file in the same directory as my original script. When I do that and use that package from within my original script, no email gets sent and there are no errors thrown.

However, if I change:

Log::Dispatch::Email::SSMTP

to

Log::Log4perl::Appender::Screen

It prints out "hi" to the screen just fine when I run my script.

So if log4perl works when sending the message to the screen, why doesn't it work when trying to send an email? And why does the same code fire an email from within the original script and not from a package? Again, there are no errors getting thrown or any kind of indication that something went wrong. And I have verified that my module gets loaded with print statements. So my module's code is definitely getting loaded but the email is still not firing.

UPDATE Here is the code when it's not working per request in comments.

maillog.pl

#!/usr/bin/perl
BEGIN { unshift @INC, "/home/steve/perl/perl-lib" }
use strict;
use warnings;
use Testy;

print 'start' . "\n";

Here is the Testy.pm package:

package Testy;
BEGIN { unshift @INC, "/home/steve/perl/perl-lib" }
use strict;
use warnings;
use Log::Log4perl qw(:easy);
use Log::Dispatch;

print 'end' . "\n";
my $appender_email = Log::Log4perl::Appender->new(
    "Log::Dispatch::Email::SSMTP",
    #"Log::Log4perl::Appender::Screen",
    threshold => "INFO",
    to => 'myemail@mail.com',
    subject => 'Perl script message'
);

my $email_logger = get_logger();
$email_logger->level($INFO);
$email_logger->add_appender($appender_email);

$email_logger->info('hi');

1;

And here is my SSMTP module located in /home/steve/perl/perl-lib/Log/Dispatch/Email/SSMTP:

package Log::Dispatch::Email::SSMTP;

use strict;
use warnings;
use Log::Dispatch::Email;
use Data::Dumper;

use base qw( Log::Dispatch::Email );
print "hi, i'm here!\n";

sub send_email {
  my $self = shift;
  my %p = @_; 
  my $to = escape ( join ',', @{$self->{to}} );
  my $subject = $self->{subject};
  my $message = $p{message};
  $message =~ s/'/'\\''/g;
  print $to . "\n";
  print $subject . "\n";
  print $message . "\n";
  print "I'm working!";

  system("echo 'To: $to\nFrom: \'Me\' <myemail\@gmail.com>\nSubject:$subject\n\n$message' | /usr/sbin/ssmtp $to");
}

sub escape {
  my $address = shift;
  $address =~ s/@/\\@/g;
  return $address;
}

1;

When I run ./maillog.pl no email is sent when using the code in the Testy package (the same code works when in maillog.pl file. However, if I uncomment Log::Dispatch::Email::SSMTP and replace with Log::Log4perl::Appender::Screen it works.

UPDATE #2 If I change Log::Log4perl::Appender::Screen to Log::Dispatch::Screen it works as well. So maybe come kind of bug in Log::Dispatch::Email?

Can you produce an example that mirrors what your code looks like when you don't receive an email? Any advice people can give is limited because they can't see the "real" code. — Hunter McMillen, Dec 03 '15 at 15:39
`Log::Dispatch` and `Log::Log4Perl` are different logging solutions; you seem to have written your email appender for `Log::Dispatch` but use it in `Log::Log4Perl`..? — Kenney, Dec 03 '15 at 15:46
@Kenney, but the same code works just fine when run directly from within maillog.pl file (see my added code above) — StevieD, Dec 03 '15 at 16:11
Strange. When I diff your first snippet with `Testy.pm` the only real difference is the email address (`myemail@email.com` vs `s@dondley....`) - you probably changed it for posting here, so that's probably not it? — Kenney, Dec 03 '15 at 16:27
Ah, thanks for letting me know. According to the doc `Log::Dispatch::EMail` will [flush when it is destroyed](http://search.cpan.org/~drolsky/Log-Dispatch/lib/Log/Dispatch/Email.pm#$email-%3EDESTROY). Maybe the destructor isn't called when it is loaded via a module? Buffering is handy to only get one mail per script run, though; you could consider another workaround like `END { $appender_email->flush() }`.. — Kenney, Dec 03 '15 at 20:05

score 0 · Accepted Answer · edited Dec 03 '15 at 20:20

Found the problem with some help from the FAQ at click here

Apparently, there is some buffering going on so emails do not get sent out immediately until some threshold for the number of messages generated is reached. Though it's still a mystery to me as to why emails are sent immediately when the code is in the main package.

So here is the code that works with the buffered property set to 0:

my $appender_email = Log::Log4perl::Appender->new(
    "Log::Dispatch::Email::SSMTP",
    threshold => "INFO",
    to => 'me@mymail.com',
    buffered => 0,
    subject => 'Perl script message'
);

log4perl run from within another package not firing messages sent through email

1 Answers1