Using the Log4Perl object as a function argument in an unused line of code makes Perl crash while destroying the objects

[sblondeel]

Hello,

Given the following script, which I tried to keep minimal:

#! /usr/bin/perl
use strict;
use warnings;
use Log::Log4perl qw(get_logger);
use English;
use File::Slurp qw( write_file );

my $USER      = $ENV{'USER'};
my $CONF_FILE = "/tmp/$USER.log4perl.properties";

write_file($CONF_FILE, << "EOCONF");
log4perl.logger=DEBUG, mail
log4perl.appender.mail=Log::Dispatch::Email::MailSend
log4perl.appender.mail.to=$USER\@localhost
log4perl.appender.mail.layout=Log::Log4perl::Layout::PatternLayout
EOCONF

print STDERR "\$PERL_VERSION: $PERL_VERSION\n";
print STDERR "\$Log::Log4perl::VERSION=$Log::Log4perl::VERSION\n";

Log::Log4perl->init($CONF_FILE);
my $logger = get_logger(q{});
$logger->error_die('FATAL ERROR');

exit 0;

sub unused_function {
  inexistent_function($logger);
}

My problem is the following:

• as is, this script crashes without sending the expected mail
• when I comment out the line "inexistent_function($logger)", it works as expected

I tested it on various configurations:

Debian 10

$ uname -a; perl -MCarp=verbose mini_crash.pl 
Linux mybox 4.19.0-18-amd64 #1 SMP Debian 4.19.208-1 (2021-09-29) x86_64 GNU/Linux
$PERL_VERSION: v5.28.1
$Log::Log4perl::VERSION=1.49
FATAL ERROR at mini_crash.pl line 23
Log messages for the mail output (a Log::Dispatch::Email::MailSend object) remain unsent but the program is terminating.
The messages are:
  FATAL ERROR

CentOS 7

$ uname -a; perl -MCarp=verbose mini_crash.pl 
Linux mybox 3.10.0-1160.36.2.el7.x86_64 #1 SMP Wed Jul 21 11:57:15 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
$PERL_VERSION: v5.16.3
$Log::Log4perl::VERSION=1.42
FATAL ERROR at mini_crash.pl line 23
backtrace: at /usr/share/perl5/vendor_perl/Mail/Send.pm line 64.
        Mail::Send::open('Mail::Send=HASH(0x17ec020)') called at /usr/share/perl5/vendor_perl/Log/Dispatch/Email/MailSend.pm line 33
        Log::Dispatch::Email::MailSend::send_email('Log::Dispatch::Email::MailSend=HASH(0x17ebf18)', 'message', 'FATAL ERROR\x{a}') called at /usr/share/perl5/vendor_perl/Log/Dispatch/Email.pm line 82
        Log::Dispatch::Email::flush('Log::Dispatch::Email::MailSend=HASH(0x17ebf18)') called at /usr/share/perl5/vendor_perl/Log/Dispatch/Email.pm line 90
        Log::Dispatch::Email::DESTROY('Log::Dispatch::Email::MailSend=HASH(0x17ebf18)') called at /usr/share/perl5/vendor_perl/Log/Log4perl/Appender.pm line 293
        eval {...} called at /usr/share/perl5/vendor_perl/Log/Log4perl/Appender.pm line 293
        Log::Log4perl::Appender::DESTROY('Log::Log4perl::Appender=HASH(0x17eba98)') called at mini_crash.pl line 0
        eval {...} called at mini_crash.pl line 0

        (in cleanup) Can't locate object method "open" via package "Mail::Mailer::sendmail" at /usr/share/perl5/vendor_perl/Mail/Send.pm line 71 during global destruction.

Note: for CentOS 7 I added "use Carp; carp 'backtrace: ';" in /usr/share/perl5/vendor_perl/Mail/Send.pm to try to see what happens. Other system modules may have their line numbers slightly off because I added some logging there and there (which I removed in the above copy-paste).

Without this call to carp (which may trigger this Carp bug fixed as of 1.47_01: https://metacpan.org/release/XSAWYERX/Carp-1.50/source/lib/Carp.pm; see the following comment starting line 330:

        # Guard our serialization of the stack from stack refcounting bugs [...]

), I still get:

$ perl /tmp/mini_crash.pl 
$PERL_VERSION: v5.16.3
$Log::Log4perl::VERSION=1.42
FATAL ERROR at /tmp/mini_crash.pl line 23

        (in cleanup) Can't locate object method "open" via package "Mail::Mailer::sendmail" at /usr/share/perl5/vendor_perl/Mail/Send.pm line 71 during global destruction.

[sblondeel]

Note: this bug is also triggered by the WARN level.

[mohawk2]

I've cut the example (which does indeed behave in the way described) down to this:

use strict;
use warnings;
use Log::Log4perl qw(get_logger);

print STDERR "\$PERL_VERSION: $^V\n";
print STDERR "\$Log::Log4perl::VERSION=$Log::Log4perl::VERSION\n";
my $USER = $ENV{'USER'};
Log::Log4perl->init(\<<"EOCONF");
log4perl.logger=DEBUG, mail
log4perl.appender.mail=Log::Dispatch::Email::MailSend
log4perl.appender.mail.to=$USER\@localhost
log4perl.appender.mail.layout=Log::Log4perl::Layout::PatternLayout
EOCONF

my $logger = get_logger(q{});
$logger->error_die('FATAL ERROR');

sub unused_function {
  inexistent_function($logger);
}

[mohawk2]

Would it work, in your application, to have a "weak reference" $logger_weak in the function, which would only call the other function if that variable was still defined? This seems like more of a thing to document, since the reference being held by that function is otherwise an insoluble problem. An alternative would be to just do get_logger() each time?