2015-10-08 17:43:56 +02:00
|
|
|
####################################################################################################################################
|
2015-10-28 11:10:36 +02:00
|
|
|
# ExecuteTest.pm - Module to execute external commands
|
2015-10-08 17:43:56 +02:00
|
|
|
####################################################################################################################################
|
2016-04-14 15:30:54 +02:00
|
|
|
package pgBackRestTest::Common::ExecuteTest;
|
2015-10-08 17:43:56 +02:00
|
|
|
|
|
|
|
####################################################################################################################################
|
|
|
|
# Perl includes
|
|
|
|
####################################################################################################################################
|
|
|
|
use strict;
|
|
|
|
use warnings FATAL => qw(all);
|
|
|
|
use Carp qw(confess);
|
|
|
|
|
|
|
|
use Exporter qw(import);
|
|
|
|
our @EXPORT = qw();
|
|
|
|
use IO::Select;
|
|
|
|
use IPC::Open3;
|
|
|
|
use POSIX ':sys_wait_h';
|
|
|
|
use Symbol 'gensym';
|
|
|
|
|
2017-06-09 23:51:41 +02:00
|
|
|
use pgBackRest::Common::Io::Handle;
|
|
|
|
use pgBackRest::Common::Io::Buffered;
|
2016-04-14 15:30:54 +02:00
|
|
|
use pgBackRest::Common::Log;
|
|
|
|
use pgBackRest::Common::Wait;
|
2015-10-08 17:43:56 +02:00
|
|
|
|
|
|
|
####################################################################################################################################
|
|
|
|
# new
|
|
|
|
####################################################################################################################################
|
|
|
|
sub new
|
|
|
|
{
|
|
|
|
my $class = shift; # Class name
|
|
|
|
|
|
|
|
# Create the class hash
|
|
|
|
my $self = {};
|
|
|
|
bless $self, $class;
|
|
|
|
|
|
|
|
# Assign function parameters, defaults, and log debug info
|
|
|
|
(
|
|
|
|
my $strOperation,
|
2016-06-24 14:12:58 +02:00
|
|
|
$self->{strCommand},
|
2015-10-08 17:43:56 +02:00
|
|
|
my $oParam
|
|
|
|
) =
|
|
|
|
logDebugParam
|
|
|
|
(
|
2016-08-11 23:32:28 +02:00
|
|
|
__PACKAGE__ . '->new', \@_,
|
2016-06-24 14:12:58 +02:00
|
|
|
{name => 'strCommand'},
|
2015-10-08 17:43:56 +02:00
|
|
|
{name => 'oParam', required => false}
|
|
|
|
);
|
|
|
|
|
|
|
|
# Load params
|
|
|
|
foreach my $strParam (sort(keys(%$oParam)))
|
|
|
|
{
|
|
|
|
$self->{$strParam} = $$oParam{$strParam};
|
|
|
|
}
|
|
|
|
|
|
|
|
# Set defaults
|
|
|
|
$self->{bSuppressError} = defined($self->{bSuppressError}) ? $self->{bSuppressError} : false;
|
2015-10-28 11:10:36 +02:00
|
|
|
$self->{bSuppressStdErr} = defined($self->{bSuppressStdErr}) ? $self->{bSuppressStdErr} : false;
|
2019-10-08 18:06:30 +02:00
|
|
|
$self->{bOutLogOnError} = defined($self->{bOutLogOnError}) ? $self->{bOutLogOnError} : true;
|
2015-10-08 17:43:56 +02:00
|
|
|
$self->{bShowOutput} = defined($self->{bShowOutput}) ? $self->{bShowOutput} : false;
|
2016-01-14 05:43:26 +02:00
|
|
|
$self->{bShowOutputAsync} = defined($self->{bShowOutputAsync}) ? $self->{bShowOutputAsync} : false;
|
2015-10-08 17:43:56 +02:00
|
|
|
$self->{iExpectedExitStatus} = defined($self->{iExpectedExitStatus}) ? $self->{iExpectedExitStatus} : 0;
|
2015-11-22 21:02:14 +02:00
|
|
|
$self->{iRetrySeconds} = defined($self->{iRetrySeconds}) ? $self->{iRetrySeconds} : undef;
|
2016-08-24 18:39:27 +02:00
|
|
|
$self->{bLogOutput} = defined($self->{bLogOutput}) ? $self->{bLogOutput} : true;
|
2015-10-08 17:43:56 +02:00
|
|
|
|
|
|
|
# Return from function and log return values if any
|
|
|
|
return logDebugReturn
|
|
|
|
(
|
|
|
|
$strOperation,
|
|
|
|
{name => 'self', value => $self}
|
|
|
|
);
|
|
|
|
}
|
|
|
|
|
|
|
|
####################################################################################################################################
|
|
|
|
# begin
|
|
|
|
####################################################################################################################################
|
|
|
|
sub begin
|
|
|
|
{
|
|
|
|
my $self = shift;
|
|
|
|
|
|
|
|
# Assign function parameters, defaults, and log debug info
|
2016-08-11 23:32:28 +02:00
|
|
|
my ($strOperation) = logDebugParam(__PACKAGE__ . '->begin');
|
2015-10-08 17:43:56 +02:00
|
|
|
|
|
|
|
$self->{strErrorLog} = '';
|
|
|
|
$self->{strOutLog} = '';
|
|
|
|
|
|
|
|
if (defined($self->{oTestLog}))
|
|
|
|
{
|
|
|
|
if (defined($self->{strComment}))
|
|
|
|
{
|
|
|
|
$self->{strFullLog} = $self->{oTestLog}->regExpAll($self->{strComment}) . "\n";
|
|
|
|
}
|
|
|
|
|
|
|
|
$self->{strFullLog} .= '> ' . $self->{oTestLog}->regExpAll($self->{strCommand}) . "\n" . ('-' x '132') . "\n";
|
|
|
|
}
|
|
|
|
|
2016-06-24 14:12:58 +02:00
|
|
|
&log(DETAIL, "executing command: $self->{strCommand}");
|
2015-10-08 17:43:56 +02:00
|
|
|
|
|
|
|
# Execute the command
|
|
|
|
$self->{hError} = gensym;
|
|
|
|
|
|
|
|
$self->{pId} = open3(undef, $self->{hOut}, $self->{hError}, $self->{strCommand});
|
|
|
|
|
2017-08-12 00:31:25 +02:00
|
|
|
# Create buffered read object
|
2017-06-15 21:20:02 +02:00
|
|
|
$self->{oIo} = new pgBackRest::Common::Io::Buffered(new pgBackRest::Common::Io::Handle('exec test', $self->{hOut}), 0, 65536);
|
|
|
|
|
2017-08-12 00:31:25 +02:00
|
|
|
# Create buffered error object
|
|
|
|
$self->{oIoError} = new pgBackRest::Common::Io::Buffered(
|
|
|
|
new pgBackRest::Common::Io::Handle('exec test', $self->{hError}), 0, 65536);
|
|
|
|
|
2017-06-15 21:20:02 +02:00
|
|
|
# Record start time and set process timeout
|
2019-09-10 18:29:36 +02:00
|
|
|
$self->{iProcessTimeout} = 300;
|
|
|
|
$self->{iProcessTimeoutTotal} = 4;
|
2017-06-25 00:04:02 +02:00
|
|
|
$self->{lTimeLast} = time();
|
2016-01-09 15:21:53 +02:00
|
|
|
|
2015-10-08 17:43:56 +02:00
|
|
|
if (!defined($self->{hError}))
|
|
|
|
{
|
|
|
|
confess 'STDERR handle is undefined';
|
|
|
|
}
|
2016-08-11 23:32:28 +02:00
|
|
|
|
|
|
|
return logDebugReturn($strOperation);
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
####################################################################################################################################
|
2015-11-22 21:02:14 +02:00
|
|
|
# endRetry
|
2015-10-08 17:43:56 +02:00
|
|
|
####################################################################################################################################
|
2015-11-22 21:02:14 +02:00
|
|
|
sub endRetry
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
|
|
|
my $self = shift;
|
|
|
|
|
|
|
|
# Assign function parameters, defaults, and log debug info
|
|
|
|
my
|
|
|
|
(
|
|
|
|
$strOperation,
|
2016-01-09 15:21:53 +02:00
|
|
|
$strTest,
|
|
|
|
$bWait
|
2015-10-08 17:43:56 +02:00
|
|
|
) =
|
|
|
|
logDebugParam
|
|
|
|
(
|
2016-08-11 23:32:28 +02:00
|
|
|
__PACKAGE__ . '->endRetry', \@_,
|
2016-01-09 15:21:53 +02:00
|
|
|
{name => 'strTest', required => false, trace => true},
|
|
|
|
{name => 'bWait', required => false, default => true, trace => true}
|
2015-10-08 17:43:56 +02:00
|
|
|
);
|
|
|
|
|
|
|
|
# Drain the output and error streams and look for test points
|
|
|
|
while(waitpid($self->{pId}, WNOHANG) == 0)
|
|
|
|
{
|
2016-01-09 15:21:53 +02:00
|
|
|
my $bFound = false;
|
2016-06-24 14:12:58 +02:00
|
|
|
|
2017-06-15 21:20:02 +02:00
|
|
|
# Error if process has been running longer than timeout
|
2017-06-25 00:04:02 +02:00
|
|
|
if (time() - $self->{lTimeLast} > $self->{iProcessTimeout})
|
2017-06-15 21:20:02 +02:00
|
|
|
{
|
2019-09-10 18:29:36 +02:00
|
|
|
if ($self->{iProcessTimeoutTotal} > 0)
|
|
|
|
{
|
|
|
|
&log(WARN, "process has been running for $self->{iProcessTimeout} seconds with no output");
|
|
|
|
$self->{iProcessTimeoutTotal}--;
|
|
|
|
$self->{lTimeLast} = time();
|
|
|
|
}
|
|
|
|
else
|
|
|
|
{
|
|
|
|
confess &log(ASSERT, "timeout waiting for process to complete: $self->{strCommand}");
|
|
|
|
}
|
2017-06-15 21:20:02 +02:00
|
|
|
}
|
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
# Drain the stdout stream and look for test points
|
2017-06-15 21:20:02 +02:00
|
|
|
while (defined(my $strLine = $self->{oIo}->readLine(true, false)))
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2017-06-25 00:04:02 +02:00
|
|
|
$self->{lTimeLast} = time();
|
|
|
|
|
2016-01-14 05:43:26 +02:00
|
|
|
$self->{strOutLog} .= "${strLine}\n";
|
2016-01-09 15:21:53 +02:00
|
|
|
$bFound = true;
|
|
|
|
|
2016-01-14 05:43:26 +02:00
|
|
|
if ($self->{bShowOutputAsync})
|
|
|
|
{
|
|
|
|
syswrite(*STDOUT, " ${strLine}\n")
|
|
|
|
}
|
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
if (defined($strTest) && testCheck($strLine, $strTest))
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2016-01-09 15:21:53 +02:00
|
|
|
&log(DEBUG, "Found test ${strTest}");
|
|
|
|
return true;
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2017-08-12 00:31:25 +02:00
|
|
|
# Drain the stderr stream
|
|
|
|
while (defined(my $strLine = $self->{oIoError}->readLine(true, false)))
|
|
|
|
{
|
|
|
|
$self->{strErrorLog} .= "${strLine}\n";
|
|
|
|
}
|
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
if (!$bWait)
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2016-02-23 16:25:22 +02:00
|
|
|
return;
|
2016-01-09 15:21:53 +02:00
|
|
|
}
|
2015-10-08 17:43:56 +02:00
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
if (!$bFound)
|
|
|
|
{
|
|
|
|
waitHiRes(.05);
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
# Check the exit status
|
|
|
|
my $iExitStatus = ${^CHILD_ERROR_NATIVE} >> 8;
|
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
# Drain the stdout stream
|
2017-06-15 21:20:02 +02:00
|
|
|
while (defined(my $strLine = $self->{oIo}->readLine(true, false)))
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2016-01-14 05:43:26 +02:00
|
|
|
$self->{strOutLog} .= "${strLine}\n";
|
|
|
|
|
|
|
|
if ($self->{bShowOutputAsync})
|
|
|
|
{
|
|
|
|
syswrite(*STDOUT, " ${strLine}\n")
|
|
|
|
}
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
2016-01-09 15:21:53 +02:00
|
|
|
# Drain the stderr stream
|
2017-08-12 00:31:25 +02:00
|
|
|
while (defined(my $strLine = $self->{oIoError}->readLine(true, false)))
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2016-01-14 05:43:26 +02:00
|
|
|
$self->{strErrorLog} .= "${strLine}\n";
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
# Pass the log to the LogTest object
|
|
|
|
if (defined($self->{oLogTest}))
|
|
|
|
{
|
2016-12-04 01:01:17 +02:00
|
|
|
if (defined($self->{strErrorLog}) && $self->{strErrorLog} ne '')
|
|
|
|
{
|
|
|
|
$self->{strOutLog} .= "STDERR:\n" . $self->{strErrorLog};
|
|
|
|
}
|
|
|
|
|
2016-08-24 18:39:27 +02:00
|
|
|
$self->{oLogTest}->logAdd($self->{strCommand}, $self->{strComment}, $self->{bLogOutput} ? $self->{strOutLog} : undef);
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
# If an error was expected then return success if that error occurred
|
|
|
|
if ($self->{iExpectedExitStatus} != 0 && $iExitStatus == $self->{iExpectedExitStatus})
|
|
|
|
{
|
|
|
|
return $iExitStatus;
|
|
|
|
}
|
|
|
|
|
|
|
|
if ($iExitStatus != 0 || ($self->{iExpectedExitStatus} != 0 && $iExitStatus != $self->{iExpectedExitStatus}))
|
|
|
|
{
|
|
|
|
if ($self->{bSuppressError})
|
|
|
|
{
|
|
|
|
&log(DEBUG, "suppressed error was ${iExitStatus}");
|
|
|
|
$self->{strErrorLog} = '';
|
|
|
|
}
|
|
|
|
else
|
|
|
|
{
|
2015-11-22 21:02:14 +02:00
|
|
|
if (defined($self->{iRetrySeconds}))
|
|
|
|
{
|
|
|
|
$self->{bRetry} = true;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
else
|
|
|
|
{
|
|
|
|
confess &log(ERROR, "command '$self->{strCommand}' returned " . $iExitStatus .
|
|
|
|
($self->{iExpectedExitStatus} != 0 ? ", but $self->{iExpectedExitStatus} was expected" : '') . "\n" .
|
2019-10-08 18:06:30 +02:00
|
|
|
($self->{strOutLog} ne '' && $self->{bOutLogOnError} ? "STDOUT (last 10,000 characters):\n" .
|
|
|
|
substr(
|
|
|
|
$self->{strOutLog}, length($self->{strOutLog}) > 10000 ?
|
|
|
|
length($self->{strOutLog}) - 10000 : 0) : '') .
|
2015-11-22 21:02:14 +02:00
|
|
|
($self->{strErrorLog} ne '' ? "STDERR:\n$self->{strErrorLog}" : ''));
|
|
|
|
}
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2015-10-28 11:10:36 +02:00
|
|
|
if ($self->{strErrorLog} ne '' && !$self->{bSuppressStdErr} && !$self->{bSuppressError})
|
2015-10-08 17:43:56 +02:00
|
|
|
{
|
2017-06-09 23:51:41 +02:00
|
|
|
confess &log(ERROR, "STDOUT:\n$self->{strOutLog}\n\noutput found on STDERR:\n$self->{strErrorLog}");
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
if ($self->{bShowOutput})
|
|
|
|
{
|
|
|
|
print "output:\n$self->{strOutLog}\n";
|
|
|
|
}
|
|
|
|
|
|
|
|
if (defined($strTest))
|
|
|
|
{
|
|
|
|
confess &log(ASSERT, "test point ${strTest} was not found");
|
|
|
|
}
|
|
|
|
|
2016-08-11 23:32:28 +02:00
|
|
|
# Return from function and log return values if any
|
|
|
|
return logDebugReturn
|
|
|
|
(
|
|
|
|
$strOperation,
|
|
|
|
{name => 'iExitStatus', value => $iExitStatus, trace => true}
|
|
|
|
);
|
2015-10-08 17:43:56 +02:00
|
|
|
}
|
|
|
|
|
2015-11-22 21:02:14 +02:00
|
|
|
####################################################################################################################################
|
|
|
|
# end
|
|
|
|
####################################################################################################################################
|
|
|
|
sub end
|
|
|
|
{
|
|
|
|
my $self = shift;
|
|
|
|
|
|
|
|
# Assign function parameters, defaults, and log debug info
|
|
|
|
my
|
|
|
|
(
|
|
|
|
$strOperation,
|
2016-01-09 15:21:53 +02:00
|
|
|
$strTest,
|
|
|
|
$bWait
|
2015-11-22 21:02:14 +02:00
|
|
|
) =
|
|
|
|
logDebugParam
|
|
|
|
(
|
2016-08-11 23:32:28 +02:00
|
|
|
__PACKAGE__ . '->end', \@_,
|
2016-01-09 15:21:53 +02:00
|
|
|
{name => 'strTest', required => false, trace => true},
|
|
|
|
{name => 'bWait', required => false, default => true, trace => true}
|
2015-11-22 21:02:14 +02:00
|
|
|
);
|
|
|
|
|
|
|
|
# If retry is not defined then run endRetry() one time
|
|
|
|
my $iExitStatus;
|
|
|
|
|
|
|
|
if (!defined($self->{iRetrySeconds}))
|
|
|
|
{
|
2016-01-09 15:21:53 +02:00
|
|
|
$iExitStatus = $self->endRetry($strTest, $bWait);
|
2015-11-22 21:02:14 +02:00
|
|
|
}
|
|
|
|
# Else loop until success or timeout
|
|
|
|
else
|
|
|
|
{
|
|
|
|
my $oWait = waitInit($self->{iRetrySeconds});
|
|
|
|
|
|
|
|
do
|
|
|
|
{
|
|
|
|
$self->{bRetry} = false;
|
|
|
|
$self->begin();
|
2016-01-09 15:21:53 +02:00
|
|
|
$iExitStatus = $self->endRetry($strTest, $bWait);
|
2015-11-22 21:02:14 +02:00
|
|
|
|
|
|
|
if ($self->{bRetry})
|
|
|
|
{
|
|
|
|
&log(TRACE, 'error executing statement - retry');
|
|
|
|
}
|
|
|
|
}
|
|
|
|
while ($self->{bRetry} && waitMore($oWait));
|
|
|
|
|
|
|
|
if ($self->{bRetry})
|
|
|
|
{
|
|
|
|
$self->begin();
|
2016-01-09 15:21:53 +02:00
|
|
|
$iExitStatus = $self->endRetry($strTest, $bWait);
|
2015-11-22 21:02:14 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2016-08-11 23:32:28 +02:00
|
|
|
# Return from function and log return values if any
|
|
|
|
return logDebugReturn
|
|
|
|
(
|
|
|
|
$strOperation,
|
|
|
|
{name => 'iExitStatus', value => $iExitStatus, trace => true}
|
|
|
|
);
|
2015-11-22 21:02:14 +02:00
|
|
|
}
|
|
|
|
|
2015-10-08 17:43:56 +02:00
|
|
|
####################################################################################################################################
|
|
|
|
# executeTest
|
|
|
|
####################################################################################################################################
|
|
|
|
sub executeTest
|
|
|
|
{
|
|
|
|
my $strCommand = shift;
|
|
|
|
my $oParam = shift;
|
|
|
|
my $strTest = shift;
|
|
|
|
|
2016-04-14 15:30:54 +02:00
|
|
|
my $oExec = new pgBackRestTest::Common::ExecuteTest($strCommand, $oParam);
|
2015-10-08 17:43:56 +02:00
|
|
|
$oExec->begin();
|
|
|
|
|
|
|
|
if (defined($strTest))
|
|
|
|
{
|
|
|
|
$oExec->end($strTest);
|
|
|
|
}
|
|
|
|
|
|
|
|
$oExec->end();
|
|
|
|
|
|
|
|
return $oExec->{strOutLog};
|
|
|
|
}
|
|
|
|
|
|
|
|
push @EXPORT, qw(executeTest);
|
|
|
|
|
|
|
|
1;
|