testbot: Add proper command line processing and --debug and --help options to the Task and VM scripts.
Francois Gouget
fgouget at codeweavers.com
Wed Aug 6 18:25:45 CDT 2014
The --debug option disables the VM status checks. This makes it possible to put a VM in maintenance mode and then manually run the scripts against it, without interference from the Engine.
This also makes the VM status checks cleaner.
The --debug option also causes log messages to be duplicated to stdout and additional traces to be printed so one can follow the script's progress. Consise timing information is also provided which makes it possible to figure out where the script spends its time.
---
testbot/bin/RevertVM.pl | 100 ++++++++++++++++++++++-----
testbot/bin/WineRunBuild.pl | 152 +++++++++++++++++++++++++++--------------
testbot/bin/WineRunReconfig.pl | 139 +++++++++++++++++++++++++------------
testbot/bin/WineRunTask.pl | 144 ++++++++++++++++++++++++++------------
testbot/lib/WineTestBot/Log.pm | 17 ++++-
5 files changed, 396 insertions(+), 156 deletions(-)
diff --git a/testbot/bin/RevertVM.pl b/testbot/bin/RevertVM.pl
index 17eb800..f370059 100755
--- a/testbot/bin/RevertVM.pl
+++ b/testbot/bin/RevertVM.pl
@@ -37,16 +37,29 @@ sub BEGIN
unshift @INC, "$::RootDir/lib";
}
}
+my $Name0 = $0;
+$Name0 =~ s+^.*/++;
use WineTestBot::Config;
use WineTestBot::Log;
use WineTestBot::VMs;
+my $Debug;
+sub Debug(@)
+{
+ print STDERR @_ if ($Debug);
+}
+
+sub Error(@)
+{
+ Debug("$Name0:error: ", @_);
+ LogMsg @_;
+}
+
sub FatalError($$)
{
my ($ErrMessage, $VM) = @_;
-
- LogMsg $ErrMessage, "\n";
+ Error "$Name0:error: $ErrMessage";
# Get the up-to-date VM status and update it if nobody else changed it
my $VMKey = $VM->GetKey();
@@ -79,35 +92,87 @@ EOF
$ENV{PATH} = "/usr/bin:/bin";
delete $ENV{ENV};
-my ($VMKey) = @ARGV;
-if (! $VMKey)
+
+# Grab the command line options
+my ($Usage, $VMKey);
+while (@ARGV)
+{
+ my $Arg = shift @ARGV;
+ if ($Arg eq "--debug")
+ {
+ $Debug = 1;
+ }
+ elsif ($Arg =~ /^(?:-\?|-h|--help)$/)
+ {
+ $Usage = 0;
+ last;
+ }
+ elsif ($Arg =~ /^???/)
+ {
+ Error "unknown option '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
+ elsif (!defined $VMKey)
+ {
+ $VMKey = $Arg;
+ }
+ else
+ {
+ Error "unexpected argument '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
+}
+
+# Check parameters
+if (!defined $Usage)
+{
+ if (!defined $VMKey)
+ {
+ Error "you must specify the VM name\n";
+ $Usage = 2;
+ }
+ elsif ($VMKey =~ /^([a-zA-Z0-9_]+)$/)
+ {
+ $VMKey = $1;
+ }
+ else
+ {
+ Error "'$VMKey' is not a valid VM name\n";
+ $Usage = 2;
+ }
+
+}
+if (defined $Usage)
{
- die "Usage: RevertVM.pl VMName";
+ print "Usage: $Name0 [--debug] [--help] VMName\n";
+ exit $Usage;
}
my $VM = CreateVMs()->GetItem($VMKey);
-if (! defined($VM))
+if (!defined $VM)
{
- LogMsg "VM $VMKey doesn't exist\n";
+ Error "VM $VMKey does not exist\n";
exit 1;
}
-
-LogMsg "Reverting $VMKey to ", $VM->IdleSnapshot, "\n";
-$VM->Status("reverting");
-my ($ErrProperty, $ErrMessage) = $VM->Save();
-if (defined($ErrMessage))
+if (!$Debug and $VM->Status ne "reverting")
{
- FatalError "Can't change status for VM $VMKey: $ErrMessage", $VM;
+ FatalError "The VM is not ready to be reverted (" . $VM->Status . ")\n", $VM;
}
+my $Start = Time();
+LogMsg "Reverting $VMKey to ", $VM->IdleSnapshot, "\n";
# Some QEmu/KVM versions are buggy and cannot revert a running VM
-$ErrMessage = $VM->PowerOff(1);
+Debug(Elapsed($Start), " Powering off the VM\n");
+my $ErrMessage = $VM->PowerOff(1);
if (defined $ErrMessage)
{
- LogMsg "$ErrMessage\n";
+ Error "$ErrMessage\n";
LogMsg "Trying the revert anyway\n";
}
+Debug(Elapsed($Start), " Reverting $VMKey to ", $VM->IdleSnapshot, "\n");
$ErrMessage = $VM->RevertToSnapshot($VM->IdleSnapshot);
if (defined($ErrMessage))
{
@@ -119,12 +184,13 @@ if (defined($ErrMessage))
$VM = CreateVMs()->GetItem($VMKey);
exit 1 if ($VM->Status ne "reverting");
$VM->Status("sleeping");
-($ErrProperty, $ErrMessage) = $VM->Save();
+(my $ErrProperty, $ErrMessage) = $VM->Save();
if (defined($ErrMessage))
{
FatalError "Can't change status for VM $VMKey: $ErrMessage", $VM;
}
+Debug(Elapsed($Start), " Trying the TestAgent connection\n");
LogMsg "Waiting for ", $VM->Name, " (up to ${WaitForToolsInVM}s per attempt)\n";
my $TA = $VM->GetAgent();
$TA->SetConnectTimeout($WaitForToolsInVM);
@@ -138,9 +204,11 @@ if (!$Success)
if ($SleepAfterRevert != 0)
{
+ Debug(Elapsed($Start), " Sleeping\n");
LogMsg "Letting ", $VM->Name, " settle for ${SleepAfterRevert}s\n";
sleep($SleepAfterRevert);
}
+Debug(Elapsed($Start), " Done\n");
# Get the up-to-date VM status and exit if someone else changed it
$VM = CreateVMs()->GetItem($VMKey);
diff --git a/testbot/bin/WineRunBuild.pl b/testbot/bin/WineRunBuild.pl
index 5c6e897..686f3e8 100755
--- a/testbot/bin/WineRunBuild.pl
+++ b/testbot/bin/WineRunBuild.pl
@@ -36,6 +36,8 @@ sub BEGIN
unshift @INC, "$::RootDir/lib";
}
}
+my $Name0 = $0;
+$Name0 =~ s+^.*/++;
use WineTestBot::Config;
use WineTestBot::Jobs;
@@ -43,9 +45,24 @@ use WineTestBot::VMs;
use WineTestBot::Log;
use WineTestBot::Engine::Notify;
+
+my $Debug;
+sub Debug(@)
+{
+ print STDERR @_ if ($Debug);
+}
+
+sub Error(@)
+{
+ Debug("$Name0:error: ", @_);
+ LogMsg @_;
+}
+
sub LogTaskError($$)
{
my ($ErrMessage, $FullErrFileName) = @_;
+ Debug("$Name0:error: $ErrMessage");
+
my $OldUMask = umask(002);
if (open(my $ErrFile, ">>", $FullErrFileName))
{
@@ -56,13 +73,14 @@ sub LogTaskError($$)
else
{
umask($OldUMask);
- LogMsg "Unable to open '$FullErrFileName' for writing: $!\n";
+ Error "Unable to open '$FullErrFileName' for writing: $!\n";
}
}
sub FatalError($$$$)
{
my ($ErrMessage, $FullErrFileName, $Job, $Task) = @_;
+ Debug("$Name0:error: $ErrMessage");
my ($JobKey, $StepKey, $TaskKey) = @{$Task->GetMasterKey()};
LogMsg "$JobKey/$StepKey/$TaskKey $ErrMessage";
@@ -120,7 +138,7 @@ sub ProcessLog($$)
{
$Status = "boterror";
$Errors = "Unable to open the log file\n";
- LogMsg "Unable to open '$FullLogFileName' for reading: $!\n";
+ Error "Unable to open '$FullLogFileName' for reading: $!\n";
}
LogTaskError($Errors, $FullErrFileName) if ($Errors);
@@ -131,57 +149,90 @@ sub ProcessLog($$)
$ENV{PATH} = "/usr/bin:/bin";
delete $ENV{ENV};
-my ($JobId, $StepNo, $TaskNo) = @ARGV;
-if (! $JobId || ! $StepNo || ! $TaskNo)
-{
- die "Usage: WineRunBuild.pl JobId StepNo TaskNo";
-}
-# Untaint parameters
-if ($JobId =~ /^(\d+)$/)
-{
- $JobId = $1;
-}
-else
+# Grab the command line options
+my $Usage;
+sub ValidateNumber($$)
{
- LogMsg "Invalid JobId $JobId\n";
- exit 1;
-}
-if ($StepNo =~ /^(\d+)$/)
-{
- $StepNo = $1;
+ my ($Name, $Value) = @_;
+
+ # Validate and untaint the value
+ return $1 if ($Value =~ /^(\d+)$/);
+ Error "$Value is not a valid $Name\n";
+ $Usage = 2;
+ return undef;
}
-else
+
+my ($JobId, $StepNo, $TaskNo);
+while (@ARGV)
{
- LogMsg "Invalid StepNo $StepNo\n";
- exit 1;
+ my $Arg = shift @ARGV;
+ if ($Arg eq "--debug")
+ {
+ $Debug = 1;
+ }
+ elsif ($Arg =~ /^(?:-\?|-h|--help)$/)
+ {
+ $Usage = 0;
+ last;
+ }
+ elsif ($Arg =~ /^???/)
+ {
+ Error "unknown option '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
+ elsif (!defined $JobId)
+ {
+ $JobId = ValidateNumber('job id', $Arg);
+ }
+ elsif (!defined $StepNo)
+ {
+ $StepNo = ValidateNumber('step number', $Arg);
+ }
+ elsif (!defined $TaskNo)
+ {
+ $TaskNo = ValidateNumber('task number', $Arg);
+ }
+ else
+ {
+ Error "unexpected argument '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
}
-if ($TaskNo =~ /^(\d+)$/)
+
+# Check parameters
+if (!defined $Usage)
{
- $TaskNo = $1;
+ if (!defined $JobId || !defined $StepNo || !defined $TaskNo)
+ {
+ Error "you must specify the job id, step number and task number\n";
+ $Usage = 2;
+ }
}
-else
+if (defined $Usage)
{
- LogMsg "Invalid TaskNo $TaskNo\n";
- exit 1;
+ print "Usage: $Name0 [--debug] [--help] JobId StepNo TaskNo\n";
+ exit $Usage;
}
my $Job = CreateJobs()->GetItem($JobId);
if (!defined $Job)
{
- LogMsg "Job $JobId doesn't exist\n";
+ Error "Job $JobId does not exist\n";
exit 1;
}
my $Step = $Job->Steps->GetItem($StepNo);
if (!defined $Step)
{
- LogMsg "Step $StepNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo of job $JobId does not exist\n";
exit 1;
}
my $Task = $Step->Tasks->GetItem($TaskNo);
if (!defined $Task)
{
- LogMsg "Step $StepNo task $TaskNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo task $TaskNo of job $JobId does not exist\n";
exit 1;
}
@@ -191,16 +242,24 @@ mkdir "$DataDir/jobs/$JobId/$StepNo";
mkdir "$DataDir/jobs/$JobId/$StepNo/$TaskNo";
umask($OldUMask);
-my $VM = $Task->VM;
-my $TA = $VM->GetAgent();
-
-LogMsg "Task $JobId/$StepNo/$TaskNo started\n";
-
my $StepDir = "$DataDir/jobs/$JobId/$StepNo";
my $TaskDir = "$StepDir/$TaskNo";
my $FullLogFileName = "$TaskDir/log";
my $FullErrFileName = "$TaskDir/err";
+my $VM = $Task->VM;
+if (!$Debug and $VM->Status ne "running")
+{
+ FatalError "The VM is not ready for use (" . $VM->Status . ")\n",
+ $FullErrFileName, $Job, $Task;
+}
+elsif ($Debug and !$VM->IsPoweredOn)
+{
+ FatalError "The VM is not powered on\n", $FullErrFileName, $Job, $Task;
+}
+my $Start = Time();
+LogMsg "Task $JobId/$StepNo/$TaskNo started\n";
+
my ($Run64, $BaseName);
foreach my $OtherStep (@{$Job->Steps->GetItems()})
{
@@ -225,22 +284,10 @@ if (!defined $BaseName)
FatalError "Can't determine base name\n", $FullErrFileName, $Job, $Task;
}
-# Normally the Engine has already set the VM status to 'running'.
-# Do it anyway in case we're called manually from the command line.
-if ($VM->Status ne "idle" and $VM->Status ne "running")
-{
- FatalError "The VM is not ready for use (" . $VM->Status . ")\n",
- $FullErrFileName, $Job, $Task;
-}
-$VM->Status('running');
-my ($ErrProperty, $ErrMessage) = $VM->Save();
-if (defined $ErrMessage)
-{
- FatalError "Can't set VM status to running: $ErrMessage\n",
- $FullErrFileName, $Job, $Task;
-}
-
+my $ErrMessage;
my $FileName = $Step->FileName;
+my $TA = $VM->GetAgent();
+Debug(Elapsed($Start), " Sending '$StepDir/$FileName'\n");
if (!$TA->SendFile("$StepDir/$FileName", "staging/$FileName", 0))
{
$ErrMessage = $TA->GetLastError();
@@ -253,12 +300,14 @@ my $Script = "#!/bin/sh\n" .
" $BaseName 32";
$Script .= ",64"if ($Run64);
$Script .= " >>Build.log 2>&1\n";
+Debug(Elapsed($Start), " Sending the script: [$Script]\n");
if (!$TA->SendFileFromString($Script, "task", $TestAgent::SENDFILE_EXE))
{
$ErrMessage = $TA->GetLastError();
FatalError "Can't send the build script to the VM: $ErrMessage\n",
$FullErrFileName, $Job, $Task;
}
+Debug(Elapsed($Start), " Running the script\n");
my $Pid = $TA->Run(["./task"], 0);
if (!$Pid or !defined $TA->Wait($Pid, $Task->Timeout, 60))
{
@@ -266,6 +315,7 @@ if (!$Pid or !defined $TA->Wait($Pid, $Task->Timeout, 60))
# Try to grab the build log before reporting the failure
}
my $NewStatus;
+Debug(Elapsed($Start), " Retrieving the build log '$FullLogFileName'\n");
if ($TA->GetFile("Build.log", $FullLogFileName))
{
$NewStatus = ProcessLog($FullLogFileName, $FullErrFileName);
@@ -324,9 +374,9 @@ if ($NewStatus eq "completed")
chmod 0664, "$OtherStepDir/$OtherFileName";
}
}
-
$TA->Disconnect();
+Debug(Elapsed($Start), " Done. New task status: $NewStatus\n");
$Task->Status($NewStatus);
$Task->ChildPid(undef);
$Task->Ended(time);
diff --git a/testbot/bin/WineRunReconfig.pl b/testbot/bin/WineRunReconfig.pl
index 2c36afc..8206ec4 100755
--- a/testbot/bin/WineRunReconfig.pl
+++ b/testbot/bin/WineRunReconfig.pl
@@ -36,6 +36,8 @@ sub BEGIN
unshift @INC, "$::RootDir/lib";
}
}
+my $Name0 = $0;
+$Name0 =~ s+^.*/++;
use WineTestBot::Config;
use WineTestBot::Jobs;
@@ -43,9 +45,24 @@ use WineTestBot::VMs;
use WineTestBot::Log;
use WineTestBot::Engine::Notify;
+
+my $Debug;
+sub Debug(@)
+{
+ print STDERR @_ if ($Debug);
+}
+
+sub Error(@)
+{
+ Debug("$Name0:error: ", @_);
+ LogMsg @_;
+}
+
sub LogTaskError($$)
{
my ($ErrMessage, $FullErrFileName) = @_;
+ Debug("$Name0:error: $ErrMessage");
+
my $OldUMask = umask(002);
if (open(my $ErrFile, ">>", $FullErrFileName))
{
@@ -56,13 +73,14 @@ sub LogTaskError($$)
else
{
umask($OldUMask);
- LogMsg "Unable to open '$FullErrFileName' for writing: $!\n";
+ Error "Unable to open '$FullErrFileName' for writing: $!\n";
}
}
sub FatalError($$$$)
{
my ($ErrMessage, $FullErrFileName, $Job, $Task) = @_;
+ Debug("$Name0:error: $ErrMessage");
my ($JobKey, $StepKey, $TaskKey) = @{$Task->GetMasterKey()};
LogMsg "$JobKey/$StepKey/$TaskKey $ErrMessage";
@@ -120,7 +138,7 @@ sub ProcessLog($$)
{
$Status = "boterror";
$Errors = "Unable to open the log file\n";
- LogMsg "Unable to open '$FullLogFileName' for reading: $!\n";
+ Error "Unable to open '$FullLogFileName' for reading: $!\n";
}
LogTaskError($Errors, $FullErrFileName) if ($Errors);
@@ -131,57 +149,91 @@ sub ProcessLog($$)
$ENV{PATH} = "/usr/bin:/bin";
delete $ENV{ENV};
-my ($JobId, $StepNo, $TaskNo) = @ARGV;
-if (! $JobId || ! $StepNo || ! $TaskNo)
-{
- die "Usage: WineRunReconfig.pl JobId StepNo TaskNo";
-}
-# Untaint parameters
-if ($JobId =~ /^(\d+)$/)
-{
- $JobId = $1;
-}
-else
-{
- LogMsg "Invalid JobId $JobId\n";
- exit 1;
-}
-if ($StepNo =~ /^(\d+)$/)
+
+# Grab the command line options
+my $Usage;
+sub ValidateNumber($$)
{
- $StepNo = $1;
+ my ($Name, $Value) = @_;
+
+ # Validate and untaint the value
+ return $1 if ($Value =~ /^(\d+)$/);
+ Error "$Value is not a valid $Name\n";
+ $Usage = 2;
+ return undef;
}
-else
+
+my ($JobId, $StepNo, $TaskNo);
+while (@ARGV)
{
- LogMsg "Invalid StepNo $StepNo\n";
- exit 1;
+ my $Arg = shift @ARGV;
+ if ($Arg eq "--debug")
+ {
+ $Debug = 1;
+ }
+ elsif ($Arg =~ /^(?:-\?|-h|--help)$/)
+ {
+ $Usage = 0;
+ last;
+ }
+ elsif ($Arg =~ /^???/)
+ {
+ Error "unknown option '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
+ elsif (!defined $JobId)
+ {
+ $JobId = ValidateNumber('job id', $Arg);
+ }
+ elsif (!defined $StepNo)
+ {
+ $StepNo = ValidateNumber('step number', $Arg);
+ }
+ elsif (!defined $TaskNo)
+ {
+ $TaskNo = ValidateNumber('task number', $Arg);
+ }
+ else
+ {
+ Error "unexpected argument '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
}
-if ($TaskNo =~ /^(\d+)$/)
+
+# Check parameters
+if (!defined $Usage)
{
- $TaskNo = $1;
+ if (!defined $JobId || !defined $StepNo || !defined $TaskNo)
+ {
+ Error "you must specify the job id, step number and task number\n";
+ $Usage = 2;
+ }
}
-else
+if (defined $Usage)
{
- LogMsg "Invalid TaskNo $TaskNo\n";
- exit 1;
+ print "Usage: $Name0 [--debug] [--help] JobId StepNo TaskNo\n";
+ exit $Usage;
}
my $Job = CreateJobs()->GetItem($JobId);
if (!defined $Job)
{
- LogMsg "Job $JobId doesn't exist\n";
+ Error "Job $JobId does not exist\n";
exit 1;
}
my $Step = $Job->Steps->GetItem($StepNo);
if (!defined $Step)
{
- LogMsg "Step $StepNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo of job $JobId does not exist\n";
exit 1;
}
my $Task = $Step->Tasks->GetItem($TaskNo);
if (!defined $Task)
{
- LogMsg "Step $StepNo task $TaskNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo task $TaskNo of job $JobId does not exist\n";
exit 1;
}
@@ -191,40 +243,37 @@ mkdir "$DataDir/jobs/$JobId/$StepNo";
mkdir "$DataDir/jobs/$JobId/$StepNo/$TaskNo";
umask($OldUMask);
-my $VM = $Task->VM;
-my $TA = $VM->GetAgent();
-
-LogMsg "Task $JobId/$StepNo/$TaskNo started\n";
-
my $StepDir = "$DataDir/jobs/$JobId/$StepNo";
my $TaskDir = "$StepDir/$TaskNo";
my $FullLogFileName = "$TaskDir/log";
my $FullErrFileName = "$TaskDir/err";
-# Normally the Engine has already set the VM status to 'running'.
-# Do it anyway in case we're called manually from the command line.
-if ($VM->Status ne "idle" and $VM->Status ne "running")
+my $VM = $Task->VM;
+if (!$Debug and $VM->Status ne "running")
{
FatalError "The VM is not ready for use (" . $VM->Status . ")\n",
$FullErrFileName, $Job, $Task;
}
-$VM->Status('running');
-my ($ErrProperty, $ErrMessage) = $VM->Save();
-if (defined $ErrMessage)
+elsif ($Debug and !$VM->IsPoweredOn)
{
- FatalError "Can't set VM status to running: $ErrMessage\n",
- $FullErrFileName, $Job, $Task;
+ FatalError "The VM is not powered on\n", $FullErrFileName, $Job, $Task;
}
+my $Start = Time();
+LogMsg "Task $JobId/$StepNo/$TaskNo started\n";
+my $ErrMessage;
my $Script = "#!/bin/sh\n" .
"rm -f Reconfig.log\n" .
"../bin/build/Reconfig.pl >>Reconfig.log 2>&1\n";
+my $TA = $VM->GetAgent();
+Debug(Elapsed($Start), " Sending the script: [$Script]\n");
if (!$TA->SendFileFromString($Script, "task", $TestAgent::SENDFILE_EXE))
{
$ErrMessage = $TA->GetLastError();
FatalError "Can't send the script to the VM: $ErrMessage\n",
$FullErrFileName, $Job, $Task;
}
+Debug(Elapsed($Start), " Running the script\n");
my $Pid = $TA->Run(["./task"], 0);
if (!$Pid or !defined $TA->Wait($Pid, $Task->Timeout, 60))
{
@@ -232,6 +281,7 @@ if (!$Pid or !defined $TA->Wait($Pid, $Task->Timeout, 60))
# Try to grab the reconfig log before reporting the failure
}
my $NewStatus;
+Debug(Elapsed($Start), " Retrieving the reconfig log '$FullLogFileName'\n");
if ($TA->GetFile("Reconfig.log", $FullLogFileName))
{
$NewStatus = ProcessLog($FullLogFileName, $FullErrFileName);
@@ -262,6 +312,7 @@ $TA->Disconnect();
if ($NewStatus eq "completed")
{
+ Debug(Elapsed($Start), " Deleting the old ", $VM->IdleSnapshot, " snapshot\n");
$ErrMessage = $VM->RemoveSnapshot($VM->IdleSnapshot);
if (defined($ErrMessage))
{
@@ -269,6 +320,7 @@ if ($NewStatus eq "completed")
$FullErrFileName, $Job, $Task;
}
+ Debug(Elapsed($Start), " Recreating the ", $VM->IdleSnapshot, " snapshot\n");
$ErrMessage = $VM->CreateSnapshot($VM->IdleSnapshot);
if (defined($ErrMessage))
{
@@ -280,6 +332,7 @@ if ($NewStatus eq "completed")
}
}
+Debug(Elapsed($Start), " Done. New task status: $NewStatus\n");
$Task->Status($NewStatus);
$Task->ChildPid(undef);
$Task->Ended(time);
diff --git a/testbot/bin/WineRunTask.pl b/testbot/bin/WineRunTask.pl
index 6cffd54..403ac2e 100755
--- a/testbot/bin/WineRunTask.pl
+++ b/testbot/bin/WineRunTask.pl
@@ -34,6 +34,8 @@ sub BEGIN
unshift @INC, "$::RootDir/lib";
}
}
+my $Name0 = $0;
+$Name0 =~ s+^.*/++;
use WineTestBot::Config;
use WineTestBot::Jobs;
@@ -41,9 +43,24 @@ use WineTestBot::VMs;
use WineTestBot::Log;
use WineTestBot::Engine::Notify;
+
+my $Debug;
+sub Debug(@)
+{
+ print STDERR @_ if ($Debug);
+}
+
+sub Error(@)
+{
+ Debug("$Name0:error: ", @_);
+ LogMsg @_;
+}
+
sub LogTaskError($$)
{
my ($ErrMessage, $FullErrFileName) = @_;
+ Debug("$Name0:error: $ErrMessage");
+
my $OldUMask = umask(002);
if (open(my $ErrFile, ">>", $FullErrFileName))
{
@@ -54,13 +71,14 @@ sub LogTaskError($$)
else
{
umask($OldUMask);
- LogMsg "Unable to open '$FullErrFileName' for writing: $!\n";
+ Error "Unable to open '$FullErrFileName' for writing: $!\n";
}
}
sub FatalError($$$$$)
{
my ($ErrMessage, $FullErrFileName, $Job, $Step, $Task) = @_;
+ Debug("$Name0:error: $ErrMessage");
my ($JobKey, $StepKey, $TaskKey) = @{$Task->GetMasterKey()};
LogMsg "$JobKey/$StepKey/$TaskKey $ErrMessage";
@@ -109,12 +127,12 @@ sub TakeScreenshot($$)
else
{
umask($OldUMask);
- LogMsg "Can't save screenshot: $!\n";
+ Error "Can't save screenshot: $!\n";
}
}
else
{
- LogMsg "Can't capture screenshot: $ErrMessage\n";
+ Error "Can't capture screenshot: $ErrMessage\n";
}
}
@@ -149,57 +167,89 @@ sub CountFailures($)
$ENV{PATH} = "/usr/bin:/bin";
delete $ENV{ENV};
-my ($JobId, $StepNo, $TaskNo) = @ARGV;
-if (! $JobId || ! $StepNo || ! $TaskNo)
+# Grab the command line options
+my $Usage;
+sub ValidateNumber($$)
{
- die "Usage: WineRunTask.pl JobId StepNo TaskNo";
-}
+ my ($Name, $Value) = @_;
-# Untaint parameters
-if ($JobId =~ /^(\d+)$/)
-{
- $JobId = $1;
+ # Validate and untaint the value
+ return $1 if ($Value =~ /^(\d+)$/);
+ Error "$Value is not a valid $Name\n";
+ $Usage = 2;
+ return undef;
}
-else
-{
- LogMsg "Invalid JobId $JobId\n";
- exit 1;
-}
-if ($StepNo =~ /^(\d+)$/)
-{
- $StepNo = $1;
-}
-else
+
+my ($JobId, $StepNo, $TaskNo);
+while (@ARGV)
{
- LogMsg "Invalid StepNo $StepNo\n";
- exit 1;
+ my $Arg = shift @ARGV;
+ if ($Arg eq "--debug")
+ {
+ $Debug = 1;
+ }
+ elsif ($Arg =~ /^(?:-\?|-h|--help)$/)
+ {
+ $Usage = 0;
+ last;
+ }
+ elsif ($Arg =~ /^???/)
+ {
+ Error "unknown option '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
+ elsif (!defined $JobId)
+ {
+ $JobId = ValidateNumber('job id', $Arg);
+ }
+ elsif (!defined $StepNo)
+ {
+ $StepNo = ValidateNumber('step number', $Arg);
+ }
+ elsif (!defined $TaskNo)
+ {
+ $TaskNo = ValidateNumber('task number', $Arg);
+ }
+ else
+ {
+ Error "unexpected argument '$Arg'\n";
+ $Usage = 2;
+ last;
+ }
}
-if ($TaskNo =~ /^(\d+)$/)
+
+# Check parameters
+if (!defined $Usage)
{
- $TaskNo = $1;
+ if (!defined $JobId || !defined $StepNo || !defined $TaskNo)
+ {
+ Error "you must specify the job id, step number and task number\n";
+ $Usage = 2;
+ }
}
-else
+if (defined $Usage)
{
- LogMsg "Invalid TaskNo $TaskNo\n";
- exit 1;
+ print "Usage: $Name0 [--debug] [--help] JobId StepNo TaskNo\n";
+ exit $Usage;
}
my $Job = CreateJobs()->GetItem($JobId);
if (!defined $Job)
{
- LogMsg "Job $JobId doesn't exist\n";
+ Error "Job $JobId does not exist\n";
exit 1;
}
my $Step = $Job->Steps->GetItem($StepNo);
if (!defined $Step)
{
- LogMsg "Step $StepNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo of job $JobId does not exist\n";
exit 1;
}
my $Task = $Step->Tasks->GetItem($TaskNo);
if (!defined $Task)
{
- LogMsg "Step $StepNo task $TaskNo of job $JobId doesn't exist\n";
+ Error "Step $StepNo task $TaskNo of job $JobId does not exist\n";
exit 1;
}
@@ -210,10 +260,6 @@ mkdir "$DataDir/jobs/$JobId/$StepNo/$TaskNo";
umask($OldUMask);
my $VM = $Task->VM;
-my $TA = $VM->GetAgent();
-
-LogMsg "Task $JobId/$StepNo/$TaskNo (" . $VM->Name . ") started\n";
-
my $RptFileName = $VM->Name . ".rpt";
my $StepDir = "$DataDir/jobs/$JobId/$StepNo";
my $TaskDir = "$StepDir/$TaskNo";
@@ -221,26 +267,27 @@ my $FullLogFileName = "$TaskDir/log";
my $FullErrFileName = "$TaskDir/err";
my $FullScreenshotFileName = "$TaskDir/screenshot.png";
-# Normally the Engine has already set the VM status to 'running'.
-# Do it anyway in case we're called manually from the command line.
-if ($VM->Status ne "idle" and $VM->Status ne "running")
+if (!$Debug and $VM->Status ne "running")
{
FatalError "The VM is not ready for use (" . $VM->Status . ")\n",
$FullErrFileName, $Job, $Step, $Task;
}
-$VM->Status('running');
-my ($ErrProperty, $ErrMessage) = $VM->Save();
-if (defined $ErrMessage)
+elsif ($Debug and !$VM->IsPoweredOn)
{
- FatalError "Can't set VM status to running: $ErrMessage\n",
- $FullErrFileName, $Job, $Step, $Task;
+ FatalError "The VM is not powered on\n", $FullErrFileName, $Job, $Step, $Task;
}
+LogMsg "Task $JobId/$StepNo/$TaskNo (" . $VM->Name . ") started\n";
+
+my $Start = Time();
+Debug("0.00 Setting the time\n");
+my $TA = $VM->GetAgent();
if (!$TA->SetTime())
{
- # Not a fatal error
- LogTaskError("Unable to set the VM system time: ". $TA->GetLastError() ."\n", $FullErrFileName);
+ # Not a fatal error
+ LogTaskError("Unable to set the VM system time: ". $TA->GetLastError() ."\n", $FullErrFileName);
}
+my $ErrMessage;
my $FileType = $Step->FileType;
if ($FileType ne "exe32" && $FileType ne "exe64")
{
@@ -248,6 +295,7 @@ if ($FileType ne "exe32" && $FileType ne "exe64")
$FullErrFileName, $Job, $Step, $Task;
}
my $FileName = $Step->FileName;
+Debug(Elapsed($Start), " Sending '$StepDir/$FileName'\n");
if (!$TA->SendFile("$StepDir/$FileName", $FileName, 0))
{
$ErrMessage = $TA->GetLastError();
@@ -257,6 +305,7 @@ if (!$TA->SendFile("$StepDir/$FileName", $FileName, 0))
my $TestLauncher = "TestLauncher" .
($FileType eq "exe64" ? "64" : "32") .
".exe";
+Debug(Elapsed($Start), " Sending '$BinDir/windows/$TestLauncher'\n");
if (!$TA->SendFile("$BinDir/windows/$TestLauncher", $TestLauncher, 0))
{
$ErrMessage = $TA->GetLastError();
@@ -319,6 +368,7 @@ elsif ($Step->Type eq "suite")
$Script .= "-q -o $RptFileName -t $Tag -m \"$EMail\" -i \"$Info\"\r\n" .
"$FileName -q -s $RptFileName\r\n";
}
+Debug(Elapsed($Start), " Sending the script: [$Script]\n");
if (!$TA->SendFileFromString($Script, "script.bat", $TestAgent::SENDFILE_EXE))
{
$ErrMessage = $TA->GetLastError();
@@ -326,6 +376,7 @@ if (!$TA->SendFileFromString($Script, "script.bat", $TestAgent::SENDFILE_EXE))
$FullErrFileName, $Job, $Step, $Task;
}
+Debug(Elapsed($Start), " Running the script\n");
my $Pid = $TA->Run(["./script.bat"], 0);
if (!$Pid or !defined $TA->Wait($Pid, $Timeout, $Keepalive))
{
@@ -333,6 +384,7 @@ if (!$Pid or !defined $TA->Wait($Pid, $Timeout, $Keepalive))
}
my $NewStatus = "boterror";
+Debug(Elapsed($Start), " Retrieving the report file '$FullLogFileName'\n");
if ($TA->GetFile($RptFileName, $FullLogFileName))
{
my $TestFailures = CountFailures($FullLogFileName);
@@ -369,6 +421,7 @@ elsif (!defined $ErrMessage)
$ErrMessage = "Can't copy log from VM: " . $TA->GetLastError();
}
+Debug(Elapsed($Start), " Taking a screenshot\n");
TakeScreenshot $VM, $FullScreenshotFileName;
if (defined $ErrMessage)
{
@@ -376,6 +429,7 @@ if (defined $ErrMessage)
}
$TA->Disconnect();
+Debug(Elapsed($Start), " Done. New task status: $NewStatus\n");
$Task->Status($NewStatus);
$Task->ChildPid(undef);
$Task->Ended(time);
diff --git a/testbot/lib/WineTestBot/Log.pm b/testbot/lib/WineTestBot/Log.pm
index 99bc03b..5c18af6 100644
--- a/testbot/lib/WineTestBot/Log.pm
+++ b/testbot/lib/WineTestBot/Log.pm
@@ -30,7 +30,7 @@ use vars qw (@ISA @EXPORT);
require Exporter;
@ISA = qw(Exporter);
- at EXPORT = qw(&LogMsg);
+ at EXPORT = qw(&LogMsg &Time &Elapsed);
my $logfile;
my $logprefix;
@@ -75,4 +75,19 @@ sub SetupRedirects()
}
}
+my $HiResTime;
+sub Time()
+{
+ local $@;
+ $HiResTime = eval { require Time::HiRes } if (!defined $HiResTime);
+ return eval { Time::HiRes::time() } if ($HiResTime);
+ return time();
+}
+
+sub Elapsed($)
+{
+ my ($Start) = @_;
+ return sprintf("%0.2f", Time()-$Start);
+}
+
1;
--
2.0.1
More information about the wine-patches
mailing list