[tools] testbot/TestWTBS: Add support for checking timeouts.

[Francois Gouget]

Timeouts can get reported in many different ways depending on whether
they are detected by TestLauncher, the WineRun* script or the Engine.
That makes a simple error matching or grep impossible. So provide
specific support for checking that a task timed out.

Signed-off-by: Francois Gouget <fgouget(a)codeweavers.com>
---
 testbot/tests/TestWTBS | 94 +++++++++++++++++++++++++++++++++---------
 1 file changed, 74 insertions(+), 20 deletions(-)

diff --git a/testbot/tests/TestWTBS b/testbot/tests/TestWTBS
index 67b1c8f96..6f78406ad 100755
--- a/testbot/tests/TestWTBS
+++ b/testbot/tests/TestWTBS
@@ -402,7 +402,10 @@ sub LoadTestInfo($)
     my $Status = ($TestInfo->{job}->{Status} ne 'completed' or
                   $TestInfo->{win32}->{TestFailures} or
                   $TestInfo->{win64}->{TestFailures} or
-                  $TestInfo->{wine}->{TestFailures}) ? "Failed" : "OK";
+                  $TestInfo->{wine}->{TestFailures} or
+                  $TestInfo->{win32}->{HasTimeout} or
+                  $TestInfo->{win64}->{HasTimeout} or
+                  $TestInfo->{wine}->{HasTimeout}) ? "Failed" : "OK";
     SetDefault($TestInfo, "webpatch", "Status", $Status);
   }
 
@@ -555,6 +558,16 @@ sub IsMailingListJob($)
   return $Job->Remarks =~ /^\[\Q$PatchesMailingList\E\] /;
 }
 
+sub IsTimeoutError($$)
+{
+  my ($GroupName, $Error) = @_;
+
+  return (($GroupName ne "" and      # Test dll or Report validation errors
+           $Error =~ /^[_a-z0-9]+: Timeout$/) or # Test unit
+          ($GroupName eq "" and      # testbot.log case
+           $Error eq "The task timed out"));
+}
+
 =pod
 =item <tasks.(report|log|testbot).groupname>
 
@@ -584,17 +597,19 @@ directives, win32 will not inherit anything from the win category.
 
 =cut
 
-sub CheckLogErrors($$$)
+sub CheckLogErrors($$$$)
 {
-  my ($LogInfo, $RefInfo, $LogKey) = @_;
+  my ($LogInfo, $RefInfo, $LogKey, $IgnoreTimeouts) = @_;
 
+  my $HasTimeout;
   foreach my $GroupName (@{$LogInfo->{ErrGroupNames}})
   {
     my $LogGroup = $LogInfo->{ErrGroups}->{$GroupName};
-
-    my $RefGroup = $RefInfo->{ErrGroups}->{$GroupName};
+    # Prevent $RefInfo from springing into existence
+    my $RefGroup = $RefInfo ? $RefInfo->{ErrGroups}->{$GroupName} : undef;
     if ($RefGroup)
     {
+      # Match the log errors to the expected errors for this group
       my $Diff = Algorithm::Diff->new($LogGroup->{Errors}, $RefGroup->{Errors},
                                       { keyGen => \&WineTestBot::LogUtils::_GetLineKey });
       my ($LogIndex, $RefIndex) = (0, 0);
@@ -613,6 +628,12 @@ sub CheckLogErrors($$$)
           foreach (1..$ExtraCount)
           {
             next if (!$LogGroup->{IsNew}->[$LogIndex]);
+            if ($IgnoreTimeouts and
+                IsTimeoutError($GroupName, $LogGroup->{Errors}->[$LogIndex]))
+            {
+              next;
+            }
+
             fail("$LogKey has an unexpected new error in $GroupName: $LogGroup->{Errors}->[$LogIndex]");
             $LogIndex++;
           }
@@ -626,27 +647,39 @@ sub CheckLogErrors($$$)
         }
       }
     }
-    else
+
+    # Check for timeouts and new errors if no error was expected for that group
+    foreach my $ErrIndex (0..@{$LogGroup->{Errors}} - 1)
     {
-      # Check that the log's extra errors are old errors
-      foreach my $ErrIndex (0..@{$LogGroup->{Errors}} - 1)
+      if (IsTimeoutError($GroupName, $LogGroup->{Errors}->[$ErrIndex]))
+      {
+        $HasTimeout = 1;
+        next if ($IgnoreTimeouts); # ignore expected timeouts
+      }
+      if ($RefInfo and !$RefGroup and $LogGroup->{IsNew}->[$ErrIndex])
       {
-        next if (!$LogGroup->{IsNew}->[$ErrIndex]);
         fail("$LogKey has an unexpected new error in $GroupName: $LogGroup->{Errors}->[$ErrIndex]");
       }
     }
   }
-  foreach my $GroupName (@{$RefInfo->{ErrGroupNames}})
-  {
-    my $LogGroup = $LogInfo->{ErrGroups}->{$GroupName};
-    next if ($LogGroup);
 
-    my $RefGroup = $RefInfo->{ErrGroups}->{$GroupName};
-    foreach my $Error (@{$RefGroup->{Errors}})
+  if ($RefInfo)
+  {
+    # Check for groups missing from the log file
+    foreach my $GroupName (@{$RefInfo->{ErrGroupNames}})
     {
-      fail("$LogKey is missing an error in $GroupName: $Error");
+      my $LogGroup = $LogInfo->{ErrGroups}->{$GroupName};
+      next if ($LogGroup);
+
+      my $RefGroup = $RefInfo->{ErrGroups}->{$GroupName};
+      foreach my $Error (@{$RefGroup->{Errors}})
+      {
+        fail("$LogKey is missing an error in $GroupName: $Error");
+      }
     }
   }
+
+  return $HasTimeout;
 }
 
 sub GrepFile($$$$;$)
@@ -716,6 +749,18 @@ By default the Status field should be 'completed'.
 Checks the value of the task's TestFailures field.
 By default the TestFailures field is not checked.
 
+=item <tasks.HasTimeout>
+
+When true verifies that the task timed out.
+This also disables reporting timeout errors as unexpected errors.
+
+Use this instead of looking for a specific error in the report because
+timeouts can get reported in many different ways depending whether they are
+detected by TestLauncher, the WineRun* script or the Engine. It can also
+depend on whether the test was the last one run by the task (in the Wine case).
+By default this check is skipped and timeout errors are reported like any
+other unexpected error.
+
 =item <tasks.(report|log|testbot).Grep>
 =item <tasks.(report|log|testbot).GrepV>
 
@@ -754,7 +799,10 @@ sub CheckTask($$$$)
     $TestUnits->{$TaskType}->{"*skipped*"} = 1;
   }
 
-  my ($ReportCount, $NewFailures) = (0, 0);
+  my $CheckTimeouts = ($Task->Status eq "completed" and
+                       CheckValue($TaskInfo->{HasTimeout}));
+
+  my ($ReportCount, $TimeoutCount, $NewFailures) = (0, 0, 0);
   foreach my $LogName (@{GetLogFileNames($Task->GetDir())})
   {
     my $LogPath = $Task->GetDir() ."/$LogName";
@@ -777,13 +825,19 @@ sub CheckTask($$$$)
       $LogType = "testbot";
     }
 
-    if ($TaskInfo->{"$LogType.errors"})
+    if ($TaskInfo->{"$LogType.errors"} or $CheckTimeouts)
     {
-      CheckLogErrors($LogInfo, $TaskInfo->{"$LogType.errors"},
-                     TaskKeyStr($Task) ."/$LogName");
+      my $HasTimeout = CheckLogErrors($LogInfo, $TaskInfo->{"$LogType.errors"},
+                                      TaskKeyStr($Task) ."/$LogName",
+                                      $TaskInfo->{HasTimeout});
+      $TimeoutCount++ if ($HasTimeout);
     }
     GrepTaskLog($Task, $LogName, $TaskInfo, "$LogType.");
   }
+  if ($CheckTimeouts)
+  {
+    ok($TimeoutCount >= $ReportCount, "Expecting 1+ timeout per report: $TimeoutCount timeouts, $ReportCount reports");
+  }
   if ($Task->Status eq "completed" and CheckValue($TaskInfo->{TestFailures}))
   {
     # Scale the expected TestFailures count with the number of times the test
-- 
2.20.1