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?

[system](http://p3rl.org/system) waits for the command to complete, unless the command starts a background process without waiting for it. When you run the command from the command line, does the prompt appear as late as it's completed? — choroba, Jul 17 '18 at 16:25
You must *add `use strict` and `use warnings`* to the top of every Perl program you write, and fix any errors or warnings that appear. This is especially important before asking the entire world for help with your code. — Borodin, Jul 17 '18 at 16:49
When the long transfer is run from the command line it waits until the transfer completes before the prompt returns. — familydweeb, Jul 17 '18 at 16:56
The script has use strict and use warnings -- there is some housekeeping code that's not included here where the command line parameters are validated and loaded into the variables you see in the code excerpt. — familydweeb, Jul 17 '18 at 16:57
Does the rest of the script run fine? If you add prints of those status messages to screen as well what do they say? Is it the same as when it works? — zdim, Jul 17 '18 at 17:23
Everything else runs fine, and the logging works fine for small transfers. If it's a big transfer the transfer itself works but nothing gets logged, like it never goes back to the script to finish up. Is there a better way than system to do the call to the AWS program? — familydweeb, Jul 17 '18 at 18:16
If the logfile is not being created, then it sounds like the command hasn't exited and might be waiting for user input. Have you tried moving the creation of the logger up prior to executing the system call? I'd also cleanup the code a little by putting the status messages into a hash lookup table instead of the if/elsif/else block. — Ron Bergin, Jul 17 '18 at 18:36
If you want more control over the execution, then use one of the IPC modules. IPC::Run or IPC::Open2 or IPC::Open3 — Ron Bergin, Jul 17 '18 at 18:39
It's still not clear -- does the script continue past `system(...)` for those long runs, when the log file isn't created? Can you add prints of status to screen? — zdim, Jul 17 '18 at 22:03

score 1 · Answer 1 · answered Jul 25 '18 at 19:01

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.

Perl logging not working on long system call

1 Answers1