From: Francois Gouget Subject: [09/25] testbot/LogUtils: Return the ParseWineTestReport() results as a single object. Message-Id: <464a9dfe8e67f303dbdd8db8d626a979ee761bda.1579000229.git.fgouget@codeweavers.com> Date: Tue, 14 Jan 2020 16:41:51 +0100 (CET) In-Reply-To: References: Rename the variable holding it to $LogInfo for consistency with the other functions as it plays the same role and may eventually carry the same information. Store the extra errors in the $LogInfo->{Extra} field and rename _AddError() to _AddExtra() to avoid confusion with AddLogError(). --- testbot/bin/UpdateTaskLogs | 11 +- testbot/bin/WineRunTask.pl | 18 ++-- testbot/bin/WineRunWineTest.pl | 18 ++-- testbot/lib/WineTestBot/LogUtils.pm | 155 +++++++++++++++++----------- 4 files changed, 114 insertions(+), 88 deletions(-) diff --git a/testbot/bin/UpdateTaskLogs b/testbot/bin/UpdateTaskLogs index d4c67bd87..758c5a7e6 100755 --- a/testbot/bin/UpdateTaskLogs +++ b/testbot/bin/UpdateTaskLogs @@ -190,19 +190,16 @@ sub BuildErrFile($$$$) my $TaskKey = Path2TaskKey($Dir); - my ($TestUnitCount, $TimeoutCount, $LogFailures, $LogErrors) = ParseWineTestReport("$Dir/$ReportName", $IsWineTest, $TaskTimedOut); - if (!defined $LogFailures and @$LogErrors == 1) - { - return "Unable to open '$TaskKey/$ReportName' for reading: $!"; - } - return undef if (!@$LogErrors); + my $LogInfo = ParseWineTestReport("$Dir/$ReportName", $IsWineTest, $TaskTimedOut); + return "$TaskKey: $LogInfo->{BadLog}" if ($LogInfo->{BadLog}); + return undef if (!@{$LogInfo->{Errors}}); Debug("$TaskKey: Creating $ReportName.err\n"); if (open(my $Log, ">", "$Dir/$ReportName.err")) { # Save the extra errors detected by ParseWineTestReport() in # $ReportName.err (see WineRunWineTest.pl). - print $Log "$_\n" for (@$LogErrors); + print $Log "$_\n" for (@{$LogInfo->{Errors}}); close($Log); return undef; } diff --git a/testbot/bin/WineRunTask.pl b/testbot/bin/WineRunTask.pl index 62bd162ee..645798bbb 100755 --- a/testbot/bin/WineRunTask.pl +++ b/testbot/bin/WineRunTask.pl @@ -556,24 +556,24 @@ if ($TA->GetFile($RptFileName, "$TaskDir/$RptFileName")) { chmod 0664, "$TaskDir/$RptFileName"; - my ($TestUnitCount, $TimeoutCount, $LogFailures, $LogErrors) = ParseWineTestReport("$TaskDir/$RptFileName", $IsWineTest, $TaskTimedOut); - $TaskTimedOut = 1 if ($TestUnitCount == $TimeoutCount); - if (!defined $LogFailures and @$LogErrors == 1) + my $LogInfo = ParseWineTestReport("$TaskDir/$RptFileName", $IsWineTest, $TaskTimedOut); + $TaskTimedOut = 1 if ($LogInfo->{TestUnitCount} == $LogInfo->{TimeoutCount}); + if ($LogInfo->{BadLog}) { # Could not open the file $NewStatus = 'boterror'; - Error "$LogErrors->[0]\n"; - LogTaskError("$LogErrors->[0]\n"); + Error "$LogInfo->{BadLog}\n"; + LogTaskError("$LogInfo->{BadLog}\n"); } else { - # $LogFailures can legitimately be undefined in case of a timeout - $TaskFailures += $LogFailures || 0; - if (@$LogErrors and open(my $Log, ">", "$TaskDir/$RptFileName.err")) + # $LogInfo->{Failures} can legitimately be undefined in case of a timeout + $TaskFailures += $LogInfo->{Failures} || 0; + if (@{$LogInfo->{Extra}} and open(my $Log, ">", "$TaskDir/$RptFileName.err")) { # Save the extra errors detected by ParseWineTestReport() in # $RptFileName.err (see WineRunWineTest.pl). - print $Log "$_\n" for (@$LogErrors); + print $Log "$_\n" for (@{$LogInfo->{Extra}}); close($Log); } } diff --git a/testbot/bin/WineRunWineTest.pl b/testbot/bin/WineRunWineTest.pl index fecbab009..66df9acec 100755 --- a/testbot/bin/WineRunWineTest.pl +++ b/testbot/bin/WineRunWineTest.pl @@ -578,20 +578,20 @@ foreach my $Mission (@{$TaskMissions->{Missions}}) { chmod 0664, "$TaskDir/$RptFileName"; - my ($TestUnitCount, $TimeoutCount, $LogFailures, $LogErrors) = ParseWineTestReport("$TaskDir/$RptFileName", $Step->FileType eq "patch", $TaskTimedOut); - $TaskTimedOut = 1 if ($TestUnitCount == $TimeoutCount); - if (!defined $LogFailures and @$LogErrors == 1) + my $LogInfo = ParseWineTestReport("$TaskDir/$RptFileName", $Step->FileType eq "patch", $TaskTimedOut); + $TaskTimedOut = 1 if ($LogInfo->{TestUnitCount} == $LogInfo->{TimeoutCount}); + if ($LogInfo->{BadLog}) { # Could not open the file $NewStatus = 'boterror'; - Error "$LogErrors->[0]\n"; - LogTaskError("$LogErrors->[0]\n"); + Error "$LogInfo->{BadLog}\n"; + LogTaskError("$LogInfo->{BadLog}\n"); } else { - # $LogFailures can legitimately be undefined in case of a timeout - $TaskFailures += $LogFailures || 0; - if (@$LogErrors and open(my $Log, ">", "$TaskDir/$RptFileName.err")) + # $LogInfo->{Failures} can legitimately be undefined in case of a timeout + $TaskFailures += $LogInfo->{Failures} || 0; + if (@{$LogInfo->{Extra}} and open(my $Log, ">", "$TaskDir/$RptFileName.err")) { # Save the extra errors detected by ParseWineTestReport() in # $RptFileName.err: @@ -600,7 +600,7 @@ foreach my $Mission (@{$TaskMissions->{Missions}}) # if there are multiple .report files in the directory. # - The .err file can be moved to the latest directory next to the # reference report. - print $Log "$_\n" for (@$LogErrors); + print $Log "$_\n" for (@{$LogInfo->{Extra}}); close($Log); } } diff --git a/testbot/lib/WineTestBot/LogUtils.pm b/testbot/lib/WineTestBot/LogUtils.pm index 4d1ddda8c..3714941fc 100644 --- a/testbot/lib/WineTestBot/LogUtils.pm +++ b/testbot/lib/WineTestBot/LogUtils.pm @@ -232,56 +232,56 @@ sub _NewCurrentUnit($$) }; } -sub _AddError($$;$) +sub _AddExtra($$;$) { - my ($Parser, $Error, $Cur) = @_; + my ($LogInfo, $Error, $Cur) = @_; $Error = "$Cur->{Dll}:$Cur->{Unit} $Error" if (defined $Cur); - push @{$Parser->{Errors}}, $Error; - $Parser->{Failures}++; + push @{$LogInfo->{Extra}}, $Error; + $LogInfo->{Failures}++; } sub _CheckUnit($$$$) { - my ($Parser, $Cur, $Unit, $Type) = @_; + my ($LogInfo, $Cur, $Unit, $Type) = @_; if ($Cur->{Units}->{$Unit} or $Cur->{Unit} eq "") { - $Parser->{IsWineTest} = 1; + $LogInfo->{IsWineTest} = 1; } # To avoid issuing many duplicate errors, # only report the first misplaced message. - elsif ($Parser->{IsWineTest} and !$Cur->{IsBroken}) + elsif ($LogInfo->{IsWineTest} and !$Cur->{IsBroken}) { - _AddError($Parser, "contains a misplaced $Type message for $Unit", $Cur); + _AddExtra($LogInfo, "contains a misplaced $Type message for $Unit", $Cur); $Cur->{IsBroken} = 1; } } sub _CheckSummaryCounter($$$$) { - my ($Parser, $Cur, $Field, $Type) = @_; + my ($LogInfo, $Cur, $Field, $Type) = @_; if ($Cur->{"Line$Field"} != 0 and $Cur->{"Summary$Field"} == 0) { - _AddError($Parser, "has unaccounted for $Type messages", $Cur); + _AddExtra($LogInfo, "has unaccounted for $Type messages", $Cur); } elsif ($Cur->{"Line$Field"} == 0 and $Cur->{"Summary$Field"} != 0) { - _AddError($Parser, "is missing some $Type messages", $Cur); + _AddExtra($LogInfo, "is missing some $Type messages", $Cur); } } sub _CloseTestUnit($$$) { - my ($Parser, $Cur, $Last) = @_; + my ($LogInfo, $Cur, $Last) = @_; # Verify the summary lines if (!$Cur->{IsBroken}) { - _CheckSummaryCounter($Parser, $Cur, "Failures", "failure"); - _CheckSummaryCounter($Parser, $Cur, "Todos", "todo"); - _CheckSummaryCounter($Parser, $Cur, "Skips", "skip"); + _CheckSummaryCounter($LogInfo, $Cur, "Failures", "failure"); + _CheckSummaryCounter($LogInfo, $Cur, "Todos", "todo"); + _CheckSummaryCounter($LogInfo, $Cur, "Skips", "skip"); } # Note that the summary lines may count some failures twice @@ -290,7 +290,7 @@ sub _CloseTestUnit($$$) if ($Cur->{UnitSize} > $MaxUnitSize) { - _AddError($Parser, "prints too much data ($Cur->{UnitSize} bytes)", $Cur); + _AddExtra($LogInfo, "prints too much data ($Cur->{UnitSize} bytes)", $Cur); } if (!$Cur->{IsBroken} and defined $Cur->{Rc}) { @@ -298,31 +298,31 @@ sub _CloseTestUnit($$$) # after the 'done' line (e.g. by subprocesses). if ($Cur->{LineFailures} != 0 and $Cur->{Rc} == 0) { - _AddError($Parser, "returned success despite having failures", $Cur); + _AddExtra($LogInfo, "returned success despite having failures", $Cur); } - elsif (!$Parser->{IsWineTest} and $Cur->{Rc} != 0) + elsif (!$LogInfo->{IsWineTest} and $Cur->{Rc} != 0) { - _AddError($Parser, "The test returned a non-zero exit code"); + _AddExtra($LogInfo, "The test returned a non-zero exit code"); } - elsif ($Parser->{IsWineTest} and $Cur->{LineFailures} == 0 and $Cur->{Rc} != 0) + elsif ($LogInfo->{IsWineTest} and $Cur->{LineFailures} == 0 and $Cur->{Rc} != 0) { - _AddError($Parser, "returned a non-zero exit code despite reporting no failures", $Cur); + _AddExtra($LogInfo, "returned a non-zero exit code despite reporting no failures", $Cur); } } # For executables TestLauncher's done line may not be recognizable. - elsif ($Parser->{IsWineTest} and !defined $Cur->{Rc}) + elsif ($LogInfo->{IsWineTest} and !defined $Cur->{Rc}) { if (!$Last) { - _AddError($Parser, "has no done line (or it is garbled)", $Cur); + _AddExtra($LogInfo, "has no done line (or it is garbled)", $Cur); } - elsif ($Last and !$Parser->{TaskTimedOut}) + elsif ($Last and !$LogInfo->{TaskTimedOut}) { - _AddError($Parser, "The report seems to have been truncated"); + _AddExtra($LogInfo, "The report seems to have been truncated"); } } - $Parser->{Failures} += $Cur->{LineFailures}; + $LogInfo->{Failures} += $Cur->{LineFailures}; } =pod @@ -330,9 +330,32 @@ sub _CloseTestUnit($$$) =item C -Parses a Wine test report and returns the number of failures and extra errors, -a list of extra errors, and whether the test timed out. +Returns a hashtable containing a summary of the WineTest report: +=over + +=item IsWineTest +True if this is a regular Wine test report, false if this is some other Windows +binary. + +=item TaskTimedOut +True if the overall task timed out waiting for the test to complete. + +=item TestUnitCount +The number of test units. + +=item TimeoutCount +The number of test units that timed out. +=item Failures +The number of failed tests. + +=item Extra +An array containing the extra errors detected during the inconsistency check. + +=item BadLog +Contains an error message if the report could not be read. + +=back =back =cut @@ -343,18 +366,18 @@ sub ParseWineTestReport($$$) my $LogFile; if (!open($LogFile, "<", $FileName)) { - my $BaseName = basename($FileName); - return (undef, undef, undef, ["Unable to open '$BaseName' for reading: $!"]); + my $LogName = basename($FileName); + return {BadLog => "Unable to open '$LogName' for reading: $!"}; } - my $Parser = { + my $LogInfo = { IsWineTest => $IsWineTest, TaskTimedOut => $TaskTimedOut, TestUnitCount => 0, TimeoutCount => 0, Failures => undef, - Errors => [], + Extra => [], }; my $Cur = _NewCurrentUnit("", ""); @@ -366,9 +389,9 @@ sub ParseWineTestReport($$$) my ($Dll, $Unit, $Type) = ($1, $2, $3); # Close the previous test unit - _CloseTestUnit($Parser, $Cur, 0) if ($Cur->{Dll} ne ""); + _CloseTestUnit($LogInfo, $Cur, 0) if ($Cur->{Dll} ne ""); $Cur = _NewCurrentUnit($Dll, $Unit); - $Parser->{TestUnitCount}++; + $LogInfo->{TestUnitCount}++; # Recognize skipped messages in case we need to skip tests in the VMs $Cur->{Rc} = 0 if ($Type eq "skipped"); @@ -383,21 +406,21 @@ sub ParseWineTestReport($$$) } else { - _AddError($Parser, "Misplaced $SubUnit subtest\n"); + _AddExtra($LogInfo, "Misplaced $SubUnit subtest\n"); } } elsif (($Cur->{Unit} ne "" and $Line =~ /($Cur->{UnitsRE})\.c:\d+: Test (?:failed|succeeded inside todo block): /) or $Line =~ /^([_a-z0-9]+)\.c:\d+: Test (?:failed|succeeded inside todo block): /) { - _CheckUnit($Parser, $Cur, $1, "failure"); + _CheckUnit($LogInfo, $Cur, $1, "failure"); $Cur->{LineFailures}++; } elsif (($Cur->{Unit} ne "" and $Line =~ /($Cur->{UnitsRE})\.c:\d+: Test marked todo: /) or $Line =~ /^([_a-z0-9]+)\.c:\d+: Test marked todo: /) { - _CheckUnit($Parser, $Cur, $1, "todo"); + _CheckUnit($LogInfo, $Cur, $1, "todo"); $Cur->{LineTodos}++; } elsif (($Cur->{Unit} ne "" and @@ -417,7 +440,7 @@ sub ParseWineTestReport($$$) # This also replaces a test summary line. $Cur->{Pids}->{0} = 1; $Cur->{SummaryFailures}++; - $Parser->{IsWineTest} = 1; + $LogInfo->{IsWineTest} = 1; $Cur->{LineFailures}++; } @@ -433,7 +456,7 @@ sub ParseWineTestReport($$$) $Cur->{Pids}->{$Pid || 0} = 1; $Cur->{SummaryFailures}++; } - _CheckUnit($Parser, $Cur, $Unit, "unhandled exception"); + _CheckUnit($LogInfo, $Cur, $Unit, "unhandled exception"); $Cur->{LineFailures}++; } elsif (($Cur->{Unit} ne "" and @@ -451,11 +474,11 @@ sub ParseWineTestReport($$$) $Cur->{SummaryFailures} += $Failures; $Cur->{SummaryTodos} += $Todos; $Cur->{SummarySkips} += $Skips; - $Parser->{IsWineTest} = 1; + $LogInfo->{IsWineTest} = 1; } else { - _CheckUnit($Parser, $Cur, $Unit, "test summary") if ($Todos or $Failures); + _CheckUnit($LogInfo, $Cur, $Unit, "test summary") if ($Todos or $Failures); } } elsif (($Cur->{Dll} ne "" and @@ -464,17 +487,17 @@ sub ParseWineTestReport($$$) { my ($Dll, $Unit, $Pid, $Rc) = ($1, $2, $3, $4); - if ($Parser->{IsWineTest} and ($Dll ne $Cur->{Dll} or $Unit ne $Cur->{Unit})) + if ($LogInfo->{IsWineTest} and ($Dll ne $Cur->{Dll} or $Unit ne $Cur->{Unit})) { # First close the current test unit taking into account # it may have been polluted by the new one. $Cur->{IsBroken} = 1; - _CloseTestUnit($Parser, $Cur, 0); + _CloseTestUnit($LogInfo, $Cur, 0); # Then switch to the new one, warning it's missing a start line, # and that its results may be inconsistent. ($Cur->{Dll}, $Cur->{Unit}) = ($Dll, $Unit); - _AddError($Parser, "had no start line (or it is garbled)", $Cur); + _AddExtra($LogInfo, "had no start line (or it is garbled)", $Cur); $Cur->{IsBroken} = 1; } @@ -482,9 +505,9 @@ sub ParseWineTestReport($$$) { # The done line will already be shown as a timeout (see JobDetails) # so record the failure but don't add an error message. - $Parser->{Failures}++; + $LogInfo->{Failures}++; $Cur->{IsBroken} = 1; - $Parser->{TimeoutCount}++; + $LogInfo->{TimeoutCount}++; } elsif ((!$Pid and !%{$Cur->{Pids}}) or ($Pid and !$Cur->{Pids}->{$Pid} and !$Cur->{Pids}->{0})) @@ -492,12 +515,12 @@ sub ParseWineTestReport($$$) # The main summary line is missing if ($Rc & 0xc0000000) { - _AddError($Parser, sprintf("%s:%s crashed (%08x)", $Dll, $Unit, $Rc & 0xffffffff)); + _AddExtra($LogInfo, sprintf("%s:%s crashed (%08x)", $Dll, $Unit, $Rc & 0xffffffff)); $Cur->{IsBroken} = 1; } - elsif ($Parser->{IsWineTest} and !$Cur->{IsBroken}) + elsif ($LogInfo->{IsWineTest} and !$Cur->{IsBroken}) { - _AddError($Parser, "$Dll:$Unit has no test summary line (early exit of the main process?)"); + _AddExtra($LogInfo, "$Dll:$Unit has no test summary line (early exit of the main process?)"); } } elsif ($Rc & 0xc0000000) @@ -511,12 +534,11 @@ sub ParseWineTestReport($$$) $Cur->{Rc} = $Rc; } } - $Cur->{IsBroken} = 1 if ($Parser->{TaskTimedOut}); - _CloseTestUnit($Parser, $Cur, 1); + $Cur->{IsBroken} = 1 if ($LogInfo->{TaskTimedOut}); + _CloseTestUnit($LogInfo, $Cur, 1); close($LogFile); - return ($Parser->{TestUnitCount}, $Parser->{TimeoutCount}, - $Parser->{Failures}, $Parser->{Errors}); + return $LogInfo; } @@ -660,18 +682,20 @@ sub GetLogLabel($) } -sub _DumpErrors($$$) +sub _DumpErrors($$) { - my ($Label, $Groups, $Errors) = @_; + my ($Label, $LogInfo) = @_; - print STDERR "$Label:\n"; - print STDERR " Groups=", scalar(@$Groups), " [", join(",", @$Groups), "]\n"; - my @ErrorKeys = sort keys %$Errors; + print STDERR "$Label: ", join(" ", keys %$LogInfo), "\n"; + my $GroupNames = $LogInfo->{ErrGroupNames}; + print STDERR " Groups=", scalar(@$GroupNames), " [", join(",", @$GroupNames), "]\n"; + my @ErrorKeys = sort keys %{$LogInfo->{Groups}}; print STDERR " Errors=", scalar(@ErrorKeys), " [", join(",", @ErrorKeys), "]\n"; - foreach my $GroupName (@$Groups) + foreach my $GroupName (@$GroupNames) { print STDERR " [$GroupName]\n"; - print STDERR " [$_]\n" for (@{$Errors->{$GroupName}->{Errors}}); + my $Group = $LogInfo->{Groups}->{$GroupName}; + print STDERR " [$_]\n" for (@{$Group->{Errors}}); } } @@ -875,10 +899,13 @@ sub _GetLineKey($) Compares the specified errors to the reference report to identify new errors. -Sets $LogInfo->{NewCount} to the total number of new errors. If there is no -reference log to identify the new errors this field is left undefined. +The $LogInfo structure is augmented with the following fields: +=over -Adds two fields to each error group: +=item NewCount +The total number of new errors or undef if the reference log could not be read. + +=item ErrGroups =over =item NewCount @@ -887,6 +914,8 @@ A count of the new errors. =item IsNew An array where entries are set to true to identify new errors. +=back + =back =back =cut -- 2.20.1