Perl logging not working on long system call

Question

I have a Perl script that is making a call to the AWS command line to upload a file to S3. It uses Log4Perl to log information about the upload. When the upload is small, a few seconds, the logging works fine -- but when the file is bigger and takes a few minutes then nothing gets logged. The file gets uploaded fine, but the log file is not created.

This is how I'm doing it:

#get start time
my @dt = localtime;
my $TransferStartDate = strftime("%Y-%m-%d", @dt);
my $TransferStartTime = strftime("%H:%M:%S", @dt);

my $aws_command = "/path/to/aws/bin/aws s3 mv $local_file s3://" . $s3_bucket;
my $aws_status = system( $aws_command);

#get stop time
@dt = localtime;
my $TransferEndDate = strftime("%Y-%m-%d", @dt);
my $TransferEndTime = strftime("%H:%M:%S", @dt);

my $log_conf = "
   log4perl.rootLogger                 = $log_level, LOG1
   log4perl.appender.LOG1              = Log::Log4perl::Appender::File
   log4perl.appender.LOG1.filename     = /path/to/logs/aws_s3_log-$TransferEndDate.txt
   log4perl.appender.LOG1.mode         = append
   log4perl.appender.LOG1.layout       = Log::Log4perl::Layout::PatternLayout
   log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n
";

Log::Log4perl::init(\$log_conf);
my $logger = Log::Log4perl->get_logger();

$logger->info( "Transfer command = $aws_command" );
$logger->info( "Transfer start = $TransferStartDate $TransferStartTime" );
$logger->info( "Transfer end = $TransferEndDate $TransferEndTime" );

#check return code 
if ( $aws_status == 0 ) 
{
    $logger->info( "Transfer completed successfully");
}
elsif ( $aws_status == 1 ) 
{
    $errstring = "s3 transfer failed status = $aws_status";
    $logger->error( $errstring );
}
elsif ( $aws_status == 2 ) 
{
    $errstring = "Syntax error on AWS S3 command status = $aws_status";   
    $logger->error( $errstring );
}
elsif ( $aws_status == 130 ) 
{
    $errstring = "transfer interrupted by Ctrl-C or other SIGINT status = $aws_status";   
    $logger->error( $errstring );
}
elsif ( $aws_status == 255 ) 
{
    $errstring = "Command failed status = $aws_status";   
    $logger->error( $errstring );
}
elsif ( $aws_status == 512 ) 
{
    $errstring = "s3 command formatted incorrectly status = $aws_status";
    $logger->error( $errstring );
}
else 
{
    $errstring = "Error with AWS s3 command status = $aws_status"; 
    $logger->error( $errstring );
}

Any ideas what I am doing wrong? Using system to make the call should cause the Perl script to stop until the upload completes, right?

Answer 1

Since you're logging to file, i would add a $|=1; in the very beginning of the script.

Also i think you should instantiate logger earlier, before launching aws_command, and launch it using ``:

$|=1;
my @dt = localtime;
my $TransferStartDate = strftime("%Y-%m-%d", @dt);
my $TransferStartTime = strftime("%H:%M:%S", @dt);

my $log_conf = "
   log4perl.rootLogger                 = $log_level, LOG1
   log4perl.appender.LOG1              = Log::Log4perl::Appender::File
   log4perl.appender.LOG1.filename     = /path/to/logs/aws_s3_log-$TransferStartDate.txt
   log4perl.appender.LOG1.mode         = append
   log4perl.appender.LOG1.layout       = Log::Log4perl::Layout::PatternLayout
   log4perl.appender.LOG1.layout.ConversionPattern = %d %p %m %n
 ";


Log::Log4perl::init(\$log_conf);
my $logger = Log::Log4perl->get_logger();

my $aws_command = "/path/to/aws/bin/aws s3 mv $local_file s3://" . $s3_bucket;
my $aws_output = `$aws_command`;
my $aws_status = $?;

#get stop time
@dt = localtime;
my $TransferEndDate = strftime("%Y-%m-%d", @dt);
my $TransferEndTime = strftime("%H:%M:%S", @dt);

$logger->info( "Transfer command = $aws_command" );
$logger->info( "Transfer result = $aws_result" );

Not sure it'll solve your issue, but might help you narrow your diagnostics.