Moving it to LogUtils.pm makes it possible to reuse it in future scripts.
Signed-off-by: Francois Gouget fgouget@codeweavers.com --- testbot/bin/WineRunTask.pl | 276 ++----------------------- testbot/lib/WineTestBot/LogUtils.pm | 310 +++++++++++++++++++++++++++- 2 files changed, 322 insertions(+), 264 deletions(-)
diff --git a/testbot/bin/WineRunTask.pl b/testbot/bin/WineRunTask.pl index 9faae28c3..821ca55ea 100755 --- a/testbot/bin/WineRunTask.pl +++ b/testbot/bin/WineRunTask.pl @@ -44,6 +44,7 @@ use WineTestBot::Config; use WineTestBot::Jobs; use WineTestBot::VMs; use WineTestBot::Log; +use WineTestBot::LogUtils; use WineTestBot::Engine::Notify;
@@ -527,275 +528,24 @@ Debug(Elapsed($Start), " Retrieving the report file to '$RptFileName'\n"); if ($TA->GetFile($RptFileName, "$TaskDir/$RptFileName")) { chmod 0664, "$TaskDir/$RptFileName"; - if (open(my $LogFile, "<", "$TaskDir/$RptFileName")) - { - # There is more than one test unit when running the full test suite so keep - # track of the current one. Note that for the TestBot we don't count or - # complain about misplaced skips. - my ($CurrentDll, $CurrentUnit) = ("", ""); - my $UnitSize = 0; - my ($LineFailures, $LineTodos, $LineSkips) = (0, 0, 0); - my ($SummaryFailures, $SummaryTodos, $SummarySkips) = (0, 0, 0); - my ($CurrentIsBroken, %CurrentPids, $CurrentRc, $LogFailures); - - sub CheckUnit($$) - { - my ($Unit, $Type) = @_; - if ($Unit eq $CurrentUnit or $CurrentUnit eq "") - { - $IsWineTest = 1; - } - # To avoid issuing many duplicate errors, - # only report the first misplaced message. - elsif ($IsWineTest and !$CurrentIsBroken) - { - LogTaskError("$CurrentDll:$CurrentUnit contains a misplaced $Type message for $Unit\n"); - $LogFailures++; - $CurrentIsBroken = 1; - } - } - - sub CheckSummaryCounter($$$) - { - my ($Count, $SCount, $Type) = @_; - - if ($Count != 0 and $SCount == 0) - { - LogTaskError("$CurrentDll:$CurrentUnit has unaccounted for $Type messages\n"); - $LogFailures++; - } - elsif ($Count == 0 and $SCount != 0) - { - LogTaskError("$CurrentDll:$CurrentUnit is missing some $Type messages\n"); - $LogFailures++; - } - } - - sub CloseTestUnit($) - { - my ($Last) = @_; - - # Verify the summary lines - if (!$CurrentIsBroken) - { - CheckSummaryCounter($LineFailures, $SummaryFailures, "failure"); - CheckSummaryCounter($LineTodos, $SummaryTodos, "todo"); - CheckSummaryCounter($LineSkips, $SummarySkips, "skip"); - } - - # Note that the summary lines may count some failures twice - # so only use them as a fallback. - $LineFailures ||= $SummaryFailures; - - if ($UnitSize > $MaxUnitSize) - { - LogTaskError("$CurrentDll:$CurrentUnit prints too much data ($UnitSize bytes)\n"); - $LogFailures++; - } - if (!$CurrentIsBroken and defined $CurrentRc) - { - # Check the exit code, particularly against failures reported - # after the 'done' line (e.g. by subprocesses). - if ($LineFailures != 0 and $CurrentRc == 0) - { - LogTaskError("$CurrentDll:$CurrentUnit returned success despite having failures\n"); - $LogFailures++; - } - elsif (!$IsWineTest and $CurrentRc != 0) - { - LogTaskError("The test returned a non-zero exit code\n"); - $LogFailures++; - } - elsif ($IsWineTest and $LineFailures == 0 and $CurrentRc != 0) - { - LogTaskError("$CurrentDll:$CurrentUnit returned a non-zero exit code despite reporting no failures\n"); - $LogFailures++; - } - } - # For executables TestLauncher's done line may not be recognizable. - elsif ($IsWineTest and !defined $CurrentRc) - { - if (!$Last) - { - LogTaskError("$CurrentDll:$CurrentUnit has no done line (or it is garbled)\n"); - } - elsif ($Last and !$TaskTimedOut) - { - LogTaskError("The report seems to have been truncated\n"); - } - $LogFailures++; - } - - $LogFailures += $LineFailures; - - $CurrentDll = $CurrentUnit = ""; - $UnitSize = 0; - $LineFailures = $LineTodos = $LineSkips = 0; - $SummaryFailures = $SummaryTodos = $SummarySkips = 0; - $CurrentIsBroken = 0; - $CurrentRc = undef; - %CurrentPids = (); - } - - foreach my $Line (<$LogFile>) - { - $UnitSize += length($Line); - if ($Line =~ m%^([_.a-z0-9-]+):([_a-z0-9]*) (start|skipped) (?:-|[/_.a-z0-9]+) (?:-|[.0-9a-f]+)\r?$%) - { - my ($Dll, $Unit, $Type) = ($1, $2, $3); - - # Close the previous test unit - CloseTestUnit(0) if ($CurrentDll ne ""); - - ($CurrentDll, $CurrentUnit) = ($Dll, $Unit); - - # Recognize skipped messages in case we need to skip tests in the VMs - $CurrentRc = 0 if ($Type eq "skipped"); - } - elsif ($Line =~ /^([_a-z0-9]+).c:\d+: Test (?:failed|succeeded inside todo block): / or - ($CurrentUnit ne "" and - $Line =~ /($CurrentUnit).c:\d+: Test (?:failed|succeeded inside todo block): /)) - { - CheckUnit($1, "failure"); - $LineFailures++; - } - elsif ($Line =~ /^([_a-z0-9]+).c:\d+: Test marked todo: / or - ($CurrentUnit ne "" and - $Line =~ /($CurrentUnit).c:\d+: Test marked todo: /)) - { - CheckUnit($1, "todo"); - $LineTodos++; - } - # TestLauncher's skip message is quite broken - elsif ($Line =~ /^([_a-z0-9]+)(?:.c)?:\d+:? Tests? skipped: / or - ($CurrentUnit ne "" and - $Line =~ /($CurrentUnit)(?:.c)?:\d+:? Tests? skipped: /)) - { - my $Unit = $1; - # Don't complain and don't count misplaced skips. Only complain if they - # are misreported (see CloseTestUnit). Also TestLauncher uses the wrong - # name in its skip message when skipping tests. - if ($Unit eq $CurrentUnit or $CurrentUnit eq "" or $Unit eq $CurrentDll) - { - $LineSkips++; - } - } - elsif ($Line =~ /^Fatal: test '([_a-z0-9]+)' does not exist/) - { - # This also replaces a test summary line. - $CurrentPids{0} = 1; - $SummaryFailures++; - $IsWineTest = 1; - - $LineFailures++; - } - elsif ($Line =~ /^(?:([0-9a-f]+):)?([_.a-z0-9]+): unhandled exception [0-9a-fA-F]{8} at / or - ($CurrentUnit ne "" and - $Line =~ /(?:([0-9a-f]+):)?($CurrentUnit): unhandled exception [0-9a-fA-F]{8} at /)) - { - my ($Pid, $Unit) = ($1, $2); - - if ($Unit eq $CurrentUnit) - { - # This also replaces a test summary line. - $CurrentPids{$Pid || 0} = 1; - $SummaryFailures++; - } - CheckUnit($Unit, "unhandled exception"); - $LineFailures++; - } - elsif ($Line =~ /^(?:([0-9a-f]+):)?([_a-z0-9]+): \d+ tests? executed ((\d+) marked as todo, (\d+) failures?), (\d+) skipped./ or - ($CurrentUnit ne "" and - $Line =~ /(?:([0-9a-f]+):)?($CurrentUnit): \d+ tests? executed ((\d+) marked as todo, (\d+) failures?), (\d+) skipped./)) - { - my ($Pid, $Unit, $Todos, $Failures, $Skips) = ($1, $2, $3, $4, $5); - - # Dlls that have only one test unit will run it even if there is - # no argument. Also TestLauncher uses the wrong name in its test - # summary line when skipping tests. - if ($Unit eq $CurrentUnit or $CurrentUnit eq "" or $Unit eq $CurrentDll) - { - # There may be more than one summary line due to child processes - $CurrentPids{$Pid || 0} = 1; - $SummaryFailures += $Failures; - $SummaryTodos += $Todos; - $SummarySkips += $Skips; - $IsWineTest = 1; - } - else - { - CheckUnit($Unit, "test summary") if ($Todos or $Failures); - } - } - elsif ($Line =~ /^([_.a-z0-9-]+):([_a-z0-9]*)(?::([0-9a-f]+))? done ((-?\d+))(?:\r?$| in)/ or - ($CurrentDll ne "" and - $Line =~ /(\Q$CurrentDll\E):([_a-z0-9]*)(?::([0-9a-f]+))? done ((-?\d+))(?:\r?$| in)/)) - { - my ($Dll, $Unit, $Pid, $Rc) = ($1, $2, $3, $4); - - if ($IsWineTest and ($Dll ne $CurrentDll or $Unit ne $CurrentUnit)) - { - # First close the current test unit taking into account - # it may have been polluted by the new one. - $LogFailures++; - $CurrentIsBroken = 1; - CloseTestUnit(0); - - # Then switch to the new one, warning it's missing a start line, - # and that its results may be inconsistent. - ($CurrentDll, $CurrentUnit) = ($Dll, $Unit); - LogTaskError("$Dll:$Unit had no start line (or it is garbled)\n"); - $CurrentIsBroken = 1; - } - - if ($Rc == 258) - { - # The done line will already be shown as a timeout (see JobDetails) - # so record the failure but don't add an error message. - $LogFailures++; - $CurrentIsBroken = 1; - $TimedOut = ($Step->Type ne "suite"); - } - elsif ((!$Pid and !%CurrentPids) or - ($Pid and !$CurrentPids{$Pid} and !$CurrentPids{0})) - { - # The main summary line is missing - if ($Rc & 0xc0000000) - { - LogTaskError(sprintf("%s:%s crashed (%08x)\n", $Dll, $Unit, $Rc & 0xffffffff)); - $LogFailures++; - $CurrentIsBroken = 1; - } - elsif ($IsWineTest and !$CurrentIsBroken) - { - LogTaskError("$Dll:$Unit has no test summary line (early exit of the main process?)\n"); - $LogFailures++; - } - } - elsif ($Rc & 0xc0000000) - { - # We know the crash happened in the main process which means we got - # an "unhandled exception" message. So there is no need to add an - # extra message or to increment the failure count. Still note that - # there may be inconsistencies (e.g. unreported todos or skips). - $CurrentIsBroken = 1; - } - $CurrentRc = $Rc; - } - } - $CurrentIsBroken = 1 if ($TaskTimedOut); - CloseTestUnit(1); - close($LogFile);
- # $LogFailures can legitimately be undefined in case of a timeout - $TaskFailures += $LogFailures || 0; - } - else + (my $LogFailures, my $LogErrors, $TimedOut) = ParseWineTestReport("$TaskDir/$RptFileName", $IsWineTest, $Step->Type eq "suite", $TaskTimedOut); + if (!defined $LogFailures and @$LogErrors == 1) { + # Could not open the file $NewStatus = 'boterror'; Error "Unable to open '$RptFileName' for reading: $!\n"; LogTaskError("Unable to open '$RptFileName' for reading: $!\n"); } + else + { + # $LogFailures can legitimately be undefined in case of a timeout + $TaskFailures += $LogFailures || 0; + foreach my $Error (@$LogErrors) + { + LogTaskError("$Error\n"); + } + } } elsif (!defined $TAError) { diff --git a/testbot/lib/WineTestBot/LogUtils.pm b/testbot/lib/WineTestBot/LogUtils.pm index 3dfd7c5e7..363f80827 100644 --- a/testbot/lib/WineTestBot/LogUtils.pm +++ b/testbot/lib/WineTestBot/LogUtils.pm @@ -27,7 +27,12 @@ WineTestBot::LogUtils - Provides functions to parse task logs
use Exporter 'import'; -our @EXPORT = qw(GetLogFileNames GetLogLabel GetLogLineCategory ParseTaskLog); +our @EXPORT = qw(GetLogFileNames GetLogLabel GetLogLineCategory + ParseTaskLog ParseWineTestReport); + +use File::Basename; + +use WineTestBot::Config; # For $MaxUnitSize
# @@ -75,6 +80,309 @@ sub ParseTaskLog($$) }
+# +# WineTest report parser +# + +sub _NewCurrentUnit($$) +{ + my ($Dll, $Unit) = @_; + + return { + # There is more than one test unit when running the full test suite so keep + # track of the current one. Note that for the TestBot we don't count or + # complain about misplaced skips. + Dll => $Dll, + Unit => $Unit, + UnitSize => 0, + LineFailures => 0, + LineTodos => 0, + LineSkips => 0, + SummaryFailures => 0, + SummaryTodos => 0, + SummarySkips => 0, + IsBroken => 0, + Rc => undef, + Pids => {}, + }; +} + +sub _AddError($$;$) +{ + my ($Parser, $Error, $Cur) = @_; + + $Error = "$Cur->{Dll}:$Cur->{Unit} $Error" if (defined $Cur); + push @{$Parser->{Errors}}, $Error; + $Parser->{Failures}++; +} + +sub _CheckUnit($$$$) +{ + my ($Parser, $Cur, $Unit, $Type) = @_; + + if ($Unit eq $Cur->{Unit} or $Cur->{Unit} eq "") + { + $Parser->{IsWineTest} = 1; + } + # To avoid issuing many duplicate errors, + # only report the first misplaced message. + elsif ($Parser->{IsWineTest} and !$Cur->{IsBroken}) + { + _AddError($Parser, "contains a misplaced $Type message for $Unit", $Cur); + $Cur->{IsBroken} = 1; + } +} + +sub _CheckSummaryCounter($$$$) +{ + my ($Parser, $Cur, $Field, $Type) = @_; + + if ($Cur->{"Line$Field"} != 0 and $Cur->{"Summary$Field"} == 0) + { + _AddError($Parser, "has unaccounted for $Type messages", $Cur); + } + elsif ($Cur->{"Line$Field"} == 0 and $Cur->{"Summary$Field"} != 0) + { + _AddError($Parser, "is missing some $Type messages", $Cur); + } +} + +sub _CloseTestUnit($$$) +{ + my ($Parser, $Cur, $Last) = @_; + + # Verify the summary lines + if (!$Cur->{IsBroken}) + { + _CheckSummaryCounter($Parser, $Cur, "Failures", "failure"); + _CheckSummaryCounter($Parser, $Cur, "Todos", "todo"); + _CheckSummaryCounter($Parser, $Cur, "Skips", "skip"); + } + + # Note that the summary lines may count some failures twice + # so only use them as a fallback. + $Cur->{LineFailures} ||= $Cur->{SummaryFailures}; + + if ($Cur->{UnitSize} > $MaxUnitSize) + { + _AddError($Parser, "prints too much data ($Cur->{UnitSize} bytes)", $Cur); + } + if (!$Cur->{IsBroken} and defined $Cur->{Rc}) + { + # Check the exit code, particularly against failures reported + # after the 'done' line (e.g. by subprocesses). + if ($Cur->{LineFailures} != 0 and $Cur->{Rc} == 0) + { + _AddError($Parser, "returned success despite having failures", $Cur); + } + elsif (!$Parser->{IsWineTest} and $Cur->{Rc} != 0) + { + _AddError($Parser, "The test returned a non-zero exit code"); + } + elsif ($Parser->{IsWineTest} and $Cur->{LineFailures} == 0 and $Cur->{Rc} != 0) + { + _AddError($Parser, "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}) + { + if (!$Last) + { + _AddError($Parser, "has no done line (or it is garbled)", $Cur); + } + elsif ($Last and !$Parser->{TaskTimedOut}) + { + _AddError($Parser, "The report seems to have been truncated"); + } + } + + $Parser->{Failures} += $Cur->{LineFailures}; +} + +=pod +=over 12 + +=item C<ParseWineTestReport()> + +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. + +=back +=cut + +sub ParseWineTestReport($$$$) +{ + my ($FileName, $IsWineTest, $IsSuite, $TaskTimedOut) = @_; + + my $LogFile; + if (!open($LogFile, "<", $FileName)) + { + my $BaseName = basename($FileName); + return (undef, ["Unable to open '$BaseName' for reading: $!"], undef); + } + + my $Parser = { + IsWineTest => $IsWineTest, + IsSuite => $IsSuite, + TaskTimedOut => $TaskTimedOut, + + TimedOut => undef, + Failures => undef, + Errors => [], + }; + + my $Cur = _NewCurrentUnit("", ""); + foreach my $Line (<$LogFile>) + { + $Cur->{UnitSize} += length($Line); + if ($Line =~ m%^([_.a-z0-9-]+):([_a-z0-9]*) (start|skipped) (?:-|[/_.a-z0-9]+) (?:-|[.0-9a-f]+)\r?$%) + { + my ($Dll, $Unit, $Type) = ($1, $2, $3); + + # Close the previous test unit + _CloseTestUnit($Parser, $Cur, 0) if ($Cur->{Dll} ne ""); + $Cur = _NewCurrentUnit($Dll, $Unit); + + # Recognize skipped messages in case we need to skip tests in the VMs + $Cur->{Rc} = 0 if ($Type eq "skipped"); + } + elsif ($Line =~ /^([_a-z0-9]+).c:\d+: Test (?:failed|succeeded inside todo block): / or + ($Cur->{Unit} ne "" and + $Line =~ /($Cur->{Unit}).c:\d+: Test (?:failed|succeeded inside todo block): /)) + { + _CheckUnit($Parser, $Cur, $1, "failure"); + $Cur->{LineFailures}++; + } + elsif ($Line =~ /^([_a-z0-9]+).c:\d+: Test marked todo: / or + ($Cur->{Unit} ne "" and + $Line =~ /($Cur->{Unit}).c:\d+: Test marked todo: /)) + { + _CheckUnit($Parser, $Cur, $1, "todo"); + $Cur->{LineTodos}++; + } + # TestLauncher's skip message is quite broken + elsif ($Line =~ /^([_a-z0-9]+)(?:.c)?:\d+:? Tests? skipped: / or + ($Cur->{Unit} ne "" and + $Line =~ /($Cur->{Unit})(?:.c)?:\d+:? Tests? skipped: /)) + { + my $Unit = $1; + # Don't complain and don't count misplaced skips. Only complain if they + # are misreported (see _CloseTestUnit). Also TestLauncher uses the wrong + # name in its skip message when skipping tests. + if ($Unit eq $Cur->{Unit} or $Cur->{Unit} eq "" or $Unit eq $Cur->{Dll}) + { + $Cur->{LineSkips}++; + } + } + elsif ($Line =~ /^Fatal: test '([_a-z0-9]+)' does not exist/) + { + # This also replaces a test summary line. + $Cur->{Pids}->{0} = 1; + $Cur->{SummaryFailures}++; + $Parser->{IsWineTest} = 1; + + $Cur->{LineFailures}++; + } + elsif ($Line =~ /^(?:([0-9a-f]+):)?([_.a-z0-9]+): unhandled exception [0-9a-fA-F]{8} at / or + ($Cur->{Unit} ne "" and + $Line =~ /(?:([0-9a-f]+):)?($Cur->{Unit}): unhandled exception [0-9a-fA-F]{8} at /)) + { + my ($Pid, $Unit) = ($1, $2); + + if ($Unit eq $Cur->{Unit}) + { + # This also replaces a test summary line. + $Cur->{Pids}->{$Pid || 0} = 1; + $Cur->{SummaryFailures}++; + } + _CheckUnit($Parser, $Cur, $Unit, "unhandled exception"); + $Cur->{LineFailures}++; + } + elsif ($Line =~ /^(?:([0-9a-f]+):)?([_a-z0-9]+): \d+ tests? executed ((\d+) marked as todo, (\d+) failures?), (\d+) skipped./ or + ($Cur->{Unit} ne "" and + $Line =~ /(?:([0-9a-f]+):)?($Cur->{Unit}): \d+ tests? executed ((\d+) marked as todo, (\d+) failures?), (\d+) skipped./)) + { + my ($Pid, $Unit, $Todos, $Failures, $Skips) = ($1, $2, $3, $4, $5); + + # Dlls that have only one test unit will run it even if there is + # no argument. Also TestLauncher uses the wrong name in its test + # summary line when skipping tests. + if ($Unit eq $Cur->{Unit} or $Cur->{Unit} eq "" or $Unit eq $Cur->{Dll}) + { + # There may be more than one summary line due to child processes + $Cur->{Pids}->{$Pid || 0} = 1; + $Cur->{SummaryFailures} += $Failures; + $Cur->{SummaryTodos} += $Todos; + $Cur->{SummarySkips} += $Skips; + $Parser->{IsWineTest} = 1; + } + else + { + _CheckUnit($Parser, $Cur, $Unit, "test summary") if ($Todos or $Failures); + } + } + elsif ($Line =~ /^([_.a-z0-9-]+):([_a-z0-9]*)(?::([0-9a-f]+))? done ((-?\d+))(?:\r?$| in)/ or + ($Cur->{Dll} ne "" and + $Line =~ /(\Q$Cur->{Dll}\E):([_a-z0-9]*)(?::([0-9a-f]+))? done ((-?\d+))(?:\r?$| in)/)) + { + my ($Dll, $Unit, $Pid, $Rc) = ($1, $2, $3, $4); + + if ($Parser->{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); + + # 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); + $Cur->{IsBroken} = 1; + } + + if ($Rc == 258) + { + # 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}++; + $Cur->{IsBroken} = 1; + $Parser->{TimedOut} = $Parser->{IsSuite}; + } + elsif ((!$Pid and !%{$Cur->{Pids}}) or + ($Pid and !$Cur->{Pids}->{$Pid} and !$Cur->{Pids}->{0})) + { + # The main summary line is missing + if ($Rc & 0xc0000000) + { + _AddError($Parser, sprintf("%s:%s crashed (%08x)", $Dll, $Unit, $Rc & 0xffffffff)); + $Cur->{IsBroken} = 1; + } + elsif ($Parser->{IsWineTest} and !$Cur->{IsBroken}) + { + _AddError($Parser, "$Dll:$Unit has no test summary line (early exit of the main process?)"); + } + } + elsif ($Rc & 0xc0000000) + { + # We know the crash happened in the main process which means we got + # an "unhandled exception" message. So there is no need to add an + # extra message or to increment the failure count. Still note that + # there may be inconsistencies (e.g. unreported todos or skips). + $Cur->{IsBroken} = 1; + } + $Cur->{Rc} = $Rc; + } + } + $Cur->{IsBroken} = 1 if ($Parser->{TaskTimedOut}); + _CloseTestUnit($Parser, $Cur, 1); + close($LogFile); + + return ($Parser->{Failures}, $Parser->{Errors}, $Parser->{TimedOut}); +} + + # # Log querying and formatting #