From: Francois Gouget Subject: [20/25] testbot: Cache the log error lists in .errors files. Message-Id: Date: Tue, 14 Jan 2020 16:43:05 +0100 (CET) In-Reply-To: References: Prior to this patch the log files needed to be parsed every time the error list is needed. Parsing the reference report and diffing its errors also needs to be repeated every time the list of new errors is needed. Both of these have a significant impact on the JobDetails page load time. So this patch lets the task scripts (WineRun*) extract the log file errors when they complete, detect the new errors, and saves the result in a .errors file stored next to the original log file. All that's needed then is to read the small .errors file to get the full errors list along with their status (old or new) which speeds up WineSendLog and JobDetails. However the task scripts cannot generate the errors cache file for the testbot.log file because that file is complete only once the task scripts exits. So the errors cache file for it is generated by the WineSendLog script once the job completes. Furthermore the .err files were used to store the validation errors detected by the ParseWineTestReport() function. These are now stored as the '.Extra' error group in the .errors files, making the .err files redundant. Then instead of showing the content of the xxx and xxx.err file in succession, the scripts either just iterate over all the error groups, or present the full content of the log first and then show the 'extra' error groups, that is those that are not tied to a specific log line number. Note: This requires running UpdateTaskLogs to create the new .errors files and to delete the obsolete .err files. Wine-Bug: https://bugs.winehq.org/show_bug.cgi?id=48035 --- testbot/bin/Janitor.pl | 2 +- testbot/bin/UpdateTaskLogs | 153 ++++++++------ testbot/bin/WineRunBuild.pl | 2 + testbot/bin/WineRunReconfig.pl | 2 + testbot/bin/WineRunTask.pl | 21 +- testbot/bin/WineRunWineTest.pl | 16 +- testbot/bin/WineSendLog.pl | 117 +++++++---- testbot/lib/WineTestBot/LogUtils.pm | 277 ++++++++++++++++++++++---- testbot/lib/WineTestBot/StepsTasks.pm | 7 - testbot/lib/WineTestBot/Tasks.pm | 3 + testbot/web/JobDetails.pl | 93 ++++----- 11 files changed, 477 insertions(+), 216 deletions(-) diff --git a/testbot/bin/Janitor.pl b/testbot/bin/Janitor.pl index ecae5be5a..a4ba817ff 100755 --- a/testbot/bin/Janitor.pl +++ b/testbot/bin/Janitor.pl @@ -314,7 +314,7 @@ if (opendir(my $dh, "$DataDir/latest")) my $Age = int((-M $FileName) + 0.5); my $TTL = $JobPurgeDays ? $JobPurgeDays - $Age : undef; - if ($Entry =~ /^([a-zA-Z0-9_]+)-job[0-9]+-[a-zA-Z0-9_]+\.report(?:\.err)?$/) + if ($Entry =~ /^([a-zA-Z0-9_]+)-job[0-9]+-[a-zA-Z0-9_]+\.report(?:\.errors)?$/) { # Keep the reference WineTest reports for all VMs even if they are # retired or scheduled for deletion. diff --git a/testbot/bin/UpdateTaskLogs b/testbot/bin/UpdateTaskLogs index b069e892e..fb0037c91 100755 --- a/testbot/bin/UpdateTaskLogs +++ b/testbot/bin/UpdateTaskLogs @@ -184,26 +184,17 @@ sub Path2TaskKey($) return $Path; } -sub BuildErrFile($$$$) +sub BuildErrorsCache($$$$;$) { - my ($Dir, $ReportName, $IsWineTest, $TaskTimedOut) = @_; + my ($Dir, $LogName, $IsWineTest, $TaskTimedOut, $Task) = @_; my $TaskKey = Path2TaskKey($Dir); + Debug("$TaskKey: Creating $LogName.errors\n"); - 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 (@{$LogInfo->{Errors}}); - close($Log); - return undef; - } - return "Unable to open '$TaskKey/$ReportName' for reading: $!"; + my $LogInfo = $LogName =~ /\.report$/ ? + ParseWineTestReport("$Dir/$LogName", $IsWineTest, $TaskTimedOut) : + ParseTaskLog("$Dir/$LogName"); + return CreateLogErrorsCache($LogInfo, $Task); } my %LatestReports; @@ -247,6 +238,7 @@ sub MoveRefReport($$;$) my ($RefDir, $RefName, $NewDir) = @_; my $RefPath = "$RefDir/$RefName"; + my $TaskKey = Path2TaskKey($NewDir); my $Rc = 0; if (-f $RefPath) @@ -268,7 +260,6 @@ sub MoveRefReport($$;$) } elsif ($RefPath ne $NewPath) { - my $TaskKey = Path2TaskKey($NewDir); my $RelRefDir = ($RefDir eq $NewDir) ? "" : "../"; Debug("$TaskKey: $RelRefDir$RefName -> $NewName\n"); if (!rename($RefPath, $NewPath)) @@ -279,6 +270,16 @@ sub MoveRefReport($$;$) } } + if (-f "$RefPath.err") + { + Debug("$TaskKey: Deleting $RefName.err\n"); + if (!unlink("$RefPath.err")) + { + Error "Could not delete '$RefName.err': $!\n"; + $Rc = 1; + } + } + return $Rc; } @@ -297,10 +298,7 @@ sub ProcessTaskLogs($$$) { next if ($LogName !~ /\.report$/); my $StepReportName = $Task->VM->Name ."_$LogName"; - foreach my $Suffix ("", ".err") - { - $Rc += MoveRefReport($StepDir, "$StepReportName$Suffix", $TaskDir); - } + $Rc += MoveRefReport($StepDir, $StepReportName, $TaskDir); } my %LogMap = ( @@ -321,10 +319,10 @@ sub ProcessTaskLogs($$$) # testbot.log is the only log which we expect to be empty. # There is not much point keeping it if that's the case. my $TestBotLog = "$TaskDir/testbot.log"; - if (-z $TestBotLog) + if (-z $TestBotLog and (!-f "$TestBotLog.errors" or -z _)) { - Debug(TaskKeyStr($Task) .": Deleting empty testbot.log\n"); - unlink $TestBotLog; + Debug(TaskKeyStr($Task) .": Deleting empty testbot.log*\n"); + unlink $TestBotLog, "$TestBotLog.errors"; } } @@ -343,13 +341,13 @@ sub ProcessTaskLogs($$$) my $RefReportName = $Task->GetRefReportName($ReportName); my $RefReportPath = "$TaskDir/$RefReportName"; - if (-f $RefReportPath or -f "$RefReportPath.err") + if (-f $RefReportPath or -f "$RefReportPath.errors") { - if (!-f "$RefReportPath.err") + if (!$OptDelete and !-f "$RefReportPath.errors") { - # (Re)Build the err file before adding the reference report to + # (Re)Build the errors file before adding the reference report to # latest/. - my $ErrMessage = BuildErrFile($StepDir, $RefReportName, 1, 0); + my $ErrMessage = BuildErrorsCache($TaskDir, $RefReportName, 1, 0); if (defined $ErrMessage) { Error "$ErrMessage\n"; @@ -363,7 +361,7 @@ sub ProcessTaskLogs($$$) Debug(TaskKeyStr($Task) .": Deleting $RefReportName*\n"); } - foreach my $Suffix ("", ".err") + foreach my $Suffix ("", ".err", ".errors") { if (!unlink "$RefReportPath$Suffix" and -e "$RefReportPath$Suffix") { @@ -380,9 +378,24 @@ sub ProcessTaskLogs($$$) $Rc = 1; } } + + # And clean up the files derived from the task's logs + foreach my $LogName (@{GetLogFileNames($TaskDir, "+old")}) + { + foreach my $Suffix (".err", ".errors") + { + next if (!-f "$TaskDir/$LogName$Suffix"); + Debug(TaskKeyStr($Task) .": Deleting $LogName$Suffix\n"); + if (!unlink "$TaskDir/$LogName$Suffix") + { + Error "Could not delete '$LogName$Suffix': $!\n"; + $Rc = 1; + } + } + } } - if (!$OptDelete and !$CollectOnly and $Task->Status eq "completed") + if (!$OptDelete and !$CollectOnly) { # Take a snapshot of the latest reference reports foreach my $LogName (@{GetLogFileNames($TaskDir)}) @@ -400,7 +413,7 @@ sub ProcessTaskLogs($$$) else { Debug(TaskKeyStr($Task) .": Snapshotting $RefReportName from ". Path2TaskKey($LatestReportPath) ."\n"); - foreach my $Suffix ("", ".err") + foreach my $Suffix ("", ".errors") { unlink "$TaskDir/$RefReportName$Suffix"; if (-f "$LatestReportPath$Suffix" and @@ -413,7 +426,7 @@ sub ProcessTaskLogs($$$) } } - # And (re)build the .err files + # And (re)build the .errors files if ($Task->Status !~ /^(?:queued|running)$/) { my ($IsWineTest, $TaskTimedOut); @@ -423,15 +436,33 @@ sub ProcessTaskLogs($$$) $TaskTimedOut = $Duration > $Task->Timeout; $IsWineTest = ($Step->Type eq "patch" or $Step->Type eq "suite"); } - foreach my $LogName (@{GetLogFileNames($TaskDir)}) + foreach my $LogName (@{GetLogFileNames($TaskDir, "+old")}) { - next if ($LogName !~ /\.report$/); - next if (-f "$TaskDir/$LogName.err"); - my $ErrMessage = BuildErrFile($TaskDir, $LogName, $IsWineTest, $TaskTimedOut); - if (defined $ErrMessage) + if ($LogName =~ /\.report$/) { - Error "$ErrMessage\n"; - $Rc = 1; + # First for the reference report + my $RefReportName = $Task->GetRefReportName($LogName); + if (!-f "$TaskDir/$RefReportName.errors" and + -f "$TaskDir/$RefReportName") + { + my $ErrMessage = BuildErrorsCache($TaskDir, $RefReportName, 1, 0); + if (defined $ErrMessage) + { + Error "$ErrMessage\n"; + $Rc = 1; + } + } + } + + # Then for the report / log itself + if (!-f "$TaskDir/$LogName.errors") + { + my $ErrMessage = BuildErrorsCache($TaskDir, $LogName, $IsWineTest, $TaskTimedOut, $Task); + if (defined $ErrMessage) + { + Error "$ErrMessage\n"; + $Rc = 1; + } } } } @@ -464,18 +495,30 @@ sub ProcessLatestReports() my $Rc = 0; my $LatestGlob = "$DataDir/latest/*.report"; - # Perform cleanups and updates + # Upgrade the naming scheme of the old reference reports + # and delete the obsolete .err files foreach my $LatestReportPath (glob("$LatestGlob $LatestGlob.err")) { my $RefReportName = basename($LatestReportPath); - next if ($RefReportName !~ /^([a-zA-Z0-9_]+\.report)(?:\.err)?$/); + next if ($RefReportName !~ /^([a-zA-Z0-9_]+_[a-zA-Z0-9_]+\.report)(?:\.err)?$/); + $RefReportName = $1; # untaint + + # MoveRefReport() also deletes .err files + $Rc += MoveRefReport("$DataDir/latest", $RefReportName); + } + + # Then perform cleanups and updates + foreach my $LatestReportPath (glob("$LatestGlob $LatestGlob.errors")) + { + my $RefReportName = basename($LatestReportPath); + next if ($RefReportName !~ /^([a-zA-Z0-9_]+-job[0-9]+-[a-zA-Z0-9_]+\.report)(?:\.errors)?$/); $RefReportName = $1; # untaint $LatestReportPath = "$DataDir/latest/$RefReportName"; if ($OptDelete or $OptRebuild) { # Delete the reports that should be deleted / rebuilt - foreach my $Suffix ("", ".err") + foreach my $Suffix ("", ".errors") { next if (!-f "$LatestReportPath$Suffix"); Debug("latest: Deleting $RefReportName$Suffix\n"); @@ -486,28 +529,26 @@ sub ProcessLatestReports() } elsif (!-f "$LatestReportPath") { - Debug("latest: Deleting orphaned $RefReportName.err\n"); - if (!unlink "$LatestReportPath.err") + Debug("latest: Deleting orphaned $RefReportName.errors\n"); + if (!unlink "$LatestReportPath.errors") { - Error "Could not delete orphaned '$LatestReportPath.err': $!\n"; + Error "Could not delete orphaned '$LatestReportPath.errors': $!\n"; $Rc = 1; } } - elsif (!$OptDelete and !-f "$LatestReportPath.err") + else { - # Build the missing .err file - my $ErrMessage = BuildErrFile("$DataDir/latest", $RefReportName, 1, 0); - if (defined $ErrMessage) + if (!-f "$LatestReportPath.errors") { - Error "$ErrMessage\n"; - $Rc = 1; + # Build the missing .errors file + my $ErrMessage = BuildErrorsCache("$DataDir/latest", $RefReportName, 1, 0); + if (defined $ErrMessage) + { + Error "$ErrMessage\n"; + $Rc = 1; + } } } - else - { - # Upgrade the naming scheme of the task's old reference reports - $Rc += MoveRefReport("$DataDir/latest", $RefReportName); - } } return $Rc; diff --git a/testbot/bin/WineRunBuild.pl b/testbot/bin/WineRunBuild.pl index b9698a9fd..c1728c66f 100755 --- a/testbot/bin/WineRunBuild.pl +++ b/testbot/bin/WineRunBuild.pl @@ -443,6 +443,8 @@ if ($TA->GetFile("Build.log", "$TaskDir/task.log")) # that explains why. $NewStatus = "badbuild"; } + my $ErrMessage = CreateLogErrorsCache($LogInfo); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); } elsif (!defined $TAError) { diff --git a/testbot/bin/WineRunReconfig.pl b/testbot/bin/WineRunReconfig.pl index bf6fc6ff4..627c96b46 100755 --- a/testbot/bin/WineRunReconfig.pl +++ b/testbot/bin/WineRunReconfig.pl @@ -443,6 +443,8 @@ if ($TA->GetFile("Reconfig.log", "$TaskDir/task.log")) MakeSecureURL(GetTaskURL($JobId, $StepNo, $TaskNo)) ."\n"); $NewStatus = "badbuild"; } + my $ErrMessage = CreateLogErrorsCache($LogInfo); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); } elsif (!defined $TAError) { diff --git a/testbot/bin/WineRunTask.pl b/testbot/bin/WineRunTask.pl index 5bd13cc7a..100857572 100755 --- a/testbot/bin/WineRunTask.pl +++ b/testbot/bin/WineRunTask.pl @@ -534,7 +534,17 @@ if (!defined $TA->Wait($Pid, $Timeout, $Keepalive)) } Debug(Elapsed($Start), " Retrieving 'Task.log'\n"); -if (!$TA->GetFile("Task.log", "$TaskDir/task.log") and !defined $TAError) +if ($TA->GetFile("Task.log", "$TaskDir/task.log")) +{ + my $LogInfo = ParseTaskLog("$TaskDir/task.log"); + if (!$LogInfo->{BadLog}) + { + my $ErrMessage = CreateLogErrorsCache($LogInfo); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); + } + # else ignore the error because this log is not critical +} +elsif (!defined $TAError) { $TAError = "An error occurred while retrieving the task log: ". $TA->GetLastError(); } @@ -561,13 +571,8 @@ if ($TA->GetFile($RptFileName, "$TaskDir/$RptFileName")) # $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 (@{$LogInfo->{Extra}}); - close($Log); - } + my $ErrMessage = CreateLogErrorsCache($LogInfo, $Task); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); } } elsif (!defined $TAError) diff --git a/testbot/bin/WineRunWineTest.pl b/testbot/bin/WineRunWineTest.pl index 6db75a7c5..8a222f352 100755 --- a/testbot/bin/WineRunWineTest.pl +++ b/testbot/bin/WineRunWineTest.pl @@ -540,6 +540,8 @@ if ($TA->GetFile("Task.log", "$TaskDir/task.log")) $TaskFailures = undef; $PossibleCrash = 1; } + my $ErrMessage = CreateLogErrorsCache($LogInfo); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); } elsif (!defined $TAError) { @@ -575,18 +577,8 @@ foreach my $RptFileName (@$ReportNames) # $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: - # - This keep the .report file clean. - # - Each .err file can be matched to its corresponding .report, even - # 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 (@{$LogInfo->{Extra}}); - close($Log); - } + my $ErrMessage = CreateLogErrorsCache($LogInfo, $Task); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); } } elsif (!defined $TAError and diff --git a/testbot/bin/WineSendLog.pl b/testbot/bin/WineSendLog.pl index 393c76a0e..84309cced 100755 --- a/testbot/bin/WineSendLog.pl +++ b/testbot/bin/WineSendLog.pl @@ -77,6 +77,60 @@ sub Error(@) } +# +# Log errors caching +# + +sub ParseTaskLogs($$) +{ + my ($Step, $Task) = @_; + + my $TaskDir = $Task->GetDir(); + + # testbot.log is the only log which we expect to be empty. + # There is not much point keeping it if that's the case. + my $TestBotLog = "$TaskDir/testbot.log"; + unlink $TestBotLog if (-z $TestBotLog and !-f "$TestBotLog.errors"); + + my ($IsWineTest, $TaskTimedOut); + if ($Task->Started and $Task->Ended) + { + my $Duration = $Task->Ended - $Task->Started; + $TaskTimedOut = $Duration > $Task->Timeout; + $IsWineTest = ($Step->Type eq "patch" or $Step->Type eq "suite"); + } + foreach my $LogName (@{GetLogFileNames($TaskDir, "+old")}) + { + next if (-f "$TaskDir/$LogName.errors"); + + my $LogInfo; + if ($LogName =~ /\.report$/) + { + $LogInfo = ParseWineTestReport("$TaskDir/$LogName", $IsWineTest, $TaskTimedOut); + } + else + { + $LogInfo = ParseTaskLog("$TaskDir/$LogName"); + } + my $ErrMessage = CreateLogErrorsCache($LogInfo, $Task); + Error "$ErrMessage\n" if (defined $ErrMessage); + } +} + +sub ParseJobLogs($) +{ + my ($Job) = @_; + + foreach my $Step (@{$Job->Steps->GetItems()}) + { + foreach my $Task (@{$Step->Tasks->GetItems()}) + { + ParseTaskLogs($Step, $Task); + } + } +} + + # # Reporting # @@ -97,27 +151,28 @@ sub GetTitle($$) sub DumpLogAndErr($$) { - my ($File, $Path) = @_; + my ($File, $LogPath) = @_; - my $PrintSeparator; - foreach my $FileName ($Path, "$Path.err") + if (open(my $LogFile, "<", $LogPath)) { - if (open(my $LogFile, "<", $FileName)) + foreach my $Line (<$LogFile>) { - my $First = 1; - foreach my $Line (<$LogFile>) - { - $Line =~ s/\s*$//; - if ($First and $PrintSeparator) - { - print $File "\n"; - $First = 0; - } - print $File "$Line\n"; - } - close($LogFile); - $PrintSeparator = 1; + $Line =~ s/\s*$//; + print $File "$Line\n"; } + close($LogFile); + } + + # And append the extra errors + my $LogInfo = LoadLogErrors($LogPath); + foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) + { + my $Group = $LogInfo->{ErrGroups}->{$GroupName}; + # Extra groups don't have a line number + next if ($Group->{LineNo}); + + print $File "\n$GroupName\n"; + print $File "$_\n" for (@{$Group->{Errors}}); } } @@ -207,12 +262,13 @@ EOF $JobErrors->{$Key}->{LogNames} = $LogNames; foreach my $LogName (@$LogNames) { - my $LogInfo = GetLogErrors("$TaskDir/$LogName"); - next if (!$LogInfo->{ErrCount}); + my $LogInfo = LoadLogErrors("$TaskDir/$LogName"); + next if (!defined $LogInfo->{BadLog} and !$LogInfo->{ErrCount}); $JobErrors->{$Key}->{HasErrors} = 1; $JobErrors->{$Key}->{$LogName} = $LogInfo; print $Sendmail "\n=== ", GetTitle($StepTask, $LogName), " ===\n"; + print $Sendmail "$LogInfo->{BadLog}\n" if (defined $LogInfo->{BadLog}); foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) { @@ -291,35 +347,17 @@ EOF # Skip if there are no errors next if (!$LogInfo->{ErrCount}); - my $AllNew; - my $RefReportPath = "$TaskDir/". $StepTask->GetRefReportName($LogName); - TagNewErrors($RefReportPath, $LogInfo); - if ($LogInfo->{NoRef}) - { - # Test reports should have reference WineTest results and if not - # reporting the errors as new would cause false positives. - next if ($LogName =~ /\.report$/); - - # Build logs don't have reference logs so for them every error is new. - $AllNew = 1; - } - elsif (!$LogInfo->{NewCount}) - { - # There is no new error - next; - } - push @Messages, "\n=== ". GetTitle($StepTask, $LogName) ." ===\n"; foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) { my $Group = $LogInfo->{ErrGroups}->{$GroupName}; - next if (!$AllNew and !$Group->{NewCount}); + next if (!$Group->{NewCount}); push @Messages, ($GroupName ? "\n$GroupName:\n" : "\n"); foreach my $ErrIndex (0..@{$Group->{Errors}} - 1) { - if ($AllNew or $Group->{IsNew}->[$ErrIndex]) + if ($Group->{IsNew}->[$ErrIndex]) { push @Messages, "$Group->{Errors}->[$ErrIndex]\n"; } @@ -510,6 +548,7 @@ if (!defined $Job) # Analyze the log, notify the developer and the Patches website # +ParseJobLogs($Job); SendLog($Job); LogMsg "Log for job $JobId sent\n"; diff --git a/testbot/lib/WineTestBot/LogUtils.pm b/testbot/lib/WineTestBot/LogUtils.pm index da73423bd..8c2fea41f 100644 --- a/testbot/lib/WineTestBot/LogUtils.pm +++ b/testbot/lib/WineTestBot/LogUtils.pm @@ -27,10 +27,11 @@ WineTestBot::LogUtils - Provides functions to parse task logs use Exporter 'import'; -our @EXPORT = qw(GetLogFileNames GetLogLabel GetLogErrors TagNewErrors +our @EXPORT = qw(GetLogFileNames GetLogLabel GetLogLineCategory GetReportLineCategory ParseTaskLog ParseWineTestReport - SnapshotLatestReport UpdateLatestReport UpdateLatestReports); + SnapshotLatestReport UpdateLatestReport UpdateLatestReports + CreateLogErrorsCache LoadLogErrors); use Algorithm::Diff; use File::Basename; @@ -624,14 +625,12 @@ sub GetLogFileNames($;$) task.log testbot.log); push @Globs, ("old_task.log", "old_testbot.log") if ($IncludeOld); - my (@Logs, %Seen); + my @Logs; foreach my $Glob (@Globs) { - foreach my $FileName (glob("'$Dir/$Glob*'")) + foreach my $FileName (glob("'$Dir/$Glob'")) { my $LogName = basename($FileName); - $LogName =~ s/\.err$//; - next if ($Seen{$LogName}); if ($LogName =~ /^([a-zA-Z0-9_]+\.report)$/) { $LogName = $1; # untaint @@ -645,13 +644,8 @@ sub GetLogFileNames($;$) # Not a valid log filename (where does this file come from?) next; } - $Seen{$LogName} = 1; - if ((-f "$Dir/$LogName" and !-z "$Dir/$LogName") or - (-f "$Dir/$LogName.err" and !-z "$Dir/$LogName.err")) - { - push @Logs, $LogName; - } + push @Logs, $LogName if (-f "$Dir/$LogName" and !-z _); } } return \@Logs; @@ -729,13 +723,20 @@ sub _AddLogGroup($$;$) return $LogInfo->{ErrGroups}->{$GroupName}; } -sub _AddLogError($$$;$) +sub _AddLogError($$$;$$) { - my ($LogInfo, $ErrGroup, $Line, $LineNo) = @_; + my ($LogInfo, $ErrGroup, $Line, $LineNo, $IsNew) = @_; push @{$ErrGroup->{Errors}}, $Line; push @{$ErrGroup->{LineNos}}, $LineNo || 0; $LogInfo->{ErrCount}++; + if ($IsNew) + { + my $ErrIndex = @{$ErrGroup->{Errors}} - 1; + $ErrGroup->{IsNew}->[$ErrIndex] = 1; + $ErrGroup->{NewCount}++; + $LogInfo->{NewCount}++; + } } =pod @@ -743,9 +744,8 @@ sub _AddLogError($$$;$) =item C -Analyzes the specified log and associated error file to filter out unimportant -messages and only return the errors, split by module (for Wine reports that's -per dll / program being tested). +Extracts the errors from the specified log file, split by module (for Wine +reports that's per dll / program being tested). Returns a hashtable containing: =over @@ -840,36 +840,177 @@ sub GetLogErrors($) _AddLogError($LogInfo, $Group, "Could not open '$LogName' for reading: $!"); } - if (open(my $LogFile, "<", "$LogPath.err")) + return $LogInfo; +} + + +# +# Log errors caching [Part 1] +# + +=pod +=over 12 + +=item C + +Loads the specified log errors file. + +The file contains two types of lines: +* GroupName lines + + Where is a unique string which would typically be the name of a + WineTest dll or program, but may also be empty or be used to specify an + extra group errors. It must not start with a space. + +* Error lines + + Where: + - is a space, as well as the spaces in the line above. + - is either 'n' for new errors, or 'o' for old ones. + - is the 1-base line number of the error in the source log file. + If there is no source line then this should be 0. + - is the error message. + +Returns the errors in the same format as TagNewErrors(). + +=back +=cut + +sub LoadLogErrors($) +{ + my ($LogPath) = @_; + + $LogPath .= ".errors"; + my $LogName = basename($LogPath); + my $LogInfo = { + LogName => $LogName, + LogPath => $LogPath, + + ErrGroupNames => [], + ErrGroups => {}, + }; + + my $ErrorsFile; + if (!open($ErrorsFile, "<", $LogPath)) + { + $LogInfo->{BadLog} = "Unable to open '$LogName' for reading: $!"; + return $LogInfo; + } + + my $CurrentGroup; + foreach my $Line (<$ErrorsFile>) { - $LogInfo->{ErrCount} ||= 0; - # Add the related extra errors - my $CurrentGroup; - my $LineNo = 0; - foreach my $Line (<$LogFile>) + chomp $Line; + my ($Type, $Property, $Value) = split / /, $Line, 3; + if ($Type eq "p") { - $LineNo++; - $Line =~ s/\s*$//; - if (!$CurrentGroup) + if (!defined $LogInfo->{$Property}) { - # Note: $GroupName must not depend on the previous content as this - # would break diffs. - my $GroupName = $IsReport ? "Report errors" : "Task errors"; - $CurrentGroup = _AddLogGroup($LogInfo, $GroupName, $LineNo); + $LogInfo->{$Property} = $Value; + } + else + { + $LogInfo->{BadLog} = "Cannot set $Property = $Value because it is already set to $LogInfo->{$Property}"; + last; } - _AddLogError($LogInfo, $CurrentGroup, $Line, $LineNo); } - close($LogFile); - } - elsif (-f "$LogPath.err") - { - my $Group = _AddLogGroup($LogInfo, "TestBot errors"); - _AddLogError($LogInfo, $Group, "Could not open '$LogName.err' for reading: $!"); + elsif ($Type eq "g") + { + $CurrentGroup = _AddLogGroup($LogInfo, $Value, $Property); + } + elsif (!$CurrentGroup) + { + $LogInfo->{BadLog} = "Got a $Type line with no group"; + last; + } + elsif ($Type eq "o") + { + _AddLogError($LogInfo, $CurrentGroup, $Value, $Property); + } + elsif ($Type eq "n") + { + _AddLogError($LogInfo, $CurrentGroup, $Value, $Property, "new"); + } + else + { + $LogInfo->{BadLog} = "Found an unknown line type ($Type)"; + last; + } } + close($ErrorsFile); return $LogInfo; } +=pod +=over 12 + +=item C<_SaveLogErrors()> + +Saves the LogInfo structure to .errors. + +The file contains lines of the form: + + +The values depend on the of the line. and must not +contain spaces while runs to the end of the line. More specifically +the line formats are: +=over + +=item p +Property lines contain (name, value) pairs. +Note that properties which can be calculated while reading the errors file +are not saved (e.g. ErrCount and NewCount). + +=item g +Group lines contain the group name and the line number of the first line of +the group in the log. Note that the first line would typically not be an +error line. +A group line should be followed by the old and new error lines in this group. + +=item o +Old error lines contain the line number of the error in the log and a verbatim +copy of that line (with CR/LF converted to a simple LF). + +=item n +The format for new error lines is identical to that for old errors but with a +different type. + +=back +=back +=cut + +sub _SaveLogErrors($) +{ + my ($LogInfo) = @_; + + my $ErrorsPath = "$LogInfo->{LogPath}.errors"; + if (open(my $ErrorsFile, ">", $ErrorsPath)) + { + foreach my $Name ("BadRef", "NoRef") + { + next if (!defined $LogInfo->{$Name}); + print $ErrorsFile "p $Name $LogInfo->{$Name}\n"; + } + foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) + { + my $Group = $LogInfo->{ErrGroups}->{$GroupName}; + print $ErrorsFile "g $Group->{LineNo} $GroupName\n"; + foreach my $Index (0..@{$Group->{Errors}} - 1) + { + my $IsNew = $Group->{IsNew}->[$Index] ? "n" : "o"; + print $ErrorsFile "$IsNew $Group->{LineNos}->[$Index] $Group->{Errors}->[$Index]\n"; + } + } + close($ErrorsFile); + + # Set the mtime so Janitor reaps both at the same time + utime time(), GetMTime($LogInfo->{LogPath}), $ErrorsPath; + return undef; + } + return "Could not open '$LogInfo->{LogName}.errors' for writing: $!"; +} + # # New error detection @@ -897,6 +1038,18 @@ sub _DumpDiff($$) } } +sub MarkAllErrorsAsNew($) +{ + my ($LogInfo) = @_; + + foreach my $Group (values %{$LogInfo->{ErrGroups}}) + { + $Group->{NewCount} = @{$Group->{Errors}}; + $Group->{IsNew}->[$_] = 1 for (0..$Group->{NewCount} - 1); + } + $LogInfo->{NewCount} = $LogInfo->{ErrCount}; +} + =pod =over 12 @@ -974,7 +1127,7 @@ sub TagNewErrors($$) return if (!$LogInfo->{ErrCount}); - my $RefInfo = GetLogErrors($RefLogPath); + my $RefInfo = LoadLogErrors($RefLogPath); if ($RefInfo->{BadLog}) { # Save the BadLog error but do not tag the errors as new: this is up to @@ -1033,6 +1186,49 @@ sub TagNewErrors($$) } +# +# Log errors caching [Part 2] +# + +sub CreateLogErrorsCache($;$) +{ + my ($ParsedInfo, $Task) = @_; + + my $LogInfo = GetLogErrors($ParsedInfo->{LogPath}); + + # Store the parser's extra errors into their own group + my $ExtraCount = $ParsedInfo->{Errors} ? @{$ParsedInfo->{Errors}} : 0; + if ($ExtraCount) + { + my $ExtraName = ($LogInfo->{LogName} =~ /\.report(?:\.errors)?$/) ? "report validation" : "task"; + $ExtraName = ucfirst($ExtraName) ." errors"; + my $Group = _AddLogGroup($LogInfo, $ExtraName); + $Group->{Errors} = $ParsedInfo->{Errors}; + my @LineNos = (0) x $ExtraCount; + $Group->{LineNos} = \@LineNos; + $LogInfo->{ErrCount} += $ExtraCount; + } + + return $LogInfo->{BadLog} if ($LogInfo->{BadLog}); + + if ($LogInfo->{LogName} !~ /\.report$/) + { + # Only test reports have reference WineTest results. + # So for other logs all errors are new. + MarkAllErrorsAsNew($LogInfo); + } + elsif ($Task and $LogInfo->{ErrCount}) + { + my $RefReportPath = $Task->GetDir() ."/". $Task->GetRefReportName($LogInfo->{LogName}); + TagNewErrors($RefReportPath, $LogInfo); + # Don't mark the errors as new if there is no reference WineTest report + # as this would cause false positives. + } + + return _SaveLogErrors($LogInfo); +} + + # # Reference report management # @@ -1061,7 +1257,7 @@ sub SnapshotLatestReport($$) my @ErrMessages; my $TaskDir = $Task->GetDir(); my $RefReportName = $Task->GetRefReportName($ReportName); - foreach my $Suffix ("", ".err") + foreach my $Suffix ("", ".errors") { next if (!-f "$DataDir/latest/$RefReportName$Suffix"); @@ -1081,9 +1277,10 @@ sub UpdateLatestReport($$$) my @ErrMessages; my $RefReportName = $Task->GetRefReportName($ReportName); - foreach my $Suffix ("", ".err") + foreach my $Suffix ("", ".errors") { # Add the new reference file even if it is empty. + # This is important for .errors files. next if (!-f "$SrcReportPath$Suffix"); unlink "$DataDir/latest/$RefReportName$Suffix"; diff --git a/testbot/lib/WineTestBot/StepsTasks.pm b/testbot/lib/WineTestBot/StepsTasks.pm index f65e6a632..463f15078 100644 --- a/testbot/lib/WineTestBot/StepsTasks.pm +++ b/testbot/lib/WineTestBot/StepsTasks.pm @@ -67,13 +67,6 @@ sub GetTaskDir($) return $self->GetStepDir() ."/". $self->TaskNo; } -# Keep in sync with WineTestBot::Task::GetRefReportName() -sub GetRefReportName($$) -{ - my ($self, $ReportName) = @_; - return $self->VM->Name ."-job000000-$ReportName"; -} - sub GetTitle($) { my ($self) = @_; diff --git a/testbot/lib/WineTestBot/Tasks.pm b/testbot/lib/WineTestBot/Tasks.pm index 541b5558e..87c501025 100644 --- a/testbot/lib/WineTestBot/Tasks.pm +++ b/testbot/lib/WineTestBot/Tasks.pm @@ -172,6 +172,9 @@ sub _SetupTask($$) } close($Src); } + + my $LogInfo = ParseTaskLog("$Dir.new/old_$Filename"); + CreateLogErrorsCache($LogInfo); } $self->RmTree(); diff --git a/testbot/web/JobDetails.pl b/testbot/web/JobDetails.pl index a4179c705..eee8df2df 100644 --- a/testbot/web/JobDetails.pl +++ b/testbot/web/JobDetails.pl @@ -346,43 +346,36 @@ sub GenerateMoreInfoLink($$$$;$$) print "
$Html
\n"; } -sub GetErrorCategory($) +sub GenerateFullLog($$$$) { - return "error"; -} + my ($self, $Dir, $LogName, $HideLog) = @_; -sub GenerateFullLog($$$$;$) -{ - my ($self, $FileName, $HideLog, $LogInfo, $Header) = @_; + my $LogInfo = LoadLogErrors("$Dir/$LogName"); my %NewLineNos; - if ($LogInfo and $LogInfo->{NewCount}) + if ($LogInfo->{ErrCount}) { foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) { my $Group = $LogInfo->{ErrGroups}->{$GroupName}; next if (!$Group->{NewCount}); - if (($FileName =~ /\.err$/) == - ($GroupName =~ /^(?:Report errors|Task errors|TestBot errors)$/)) + for my $ErrIndex (0..@{$Group->{Errors}} - 1) { - for my $ErrIndex (0..@{$Group->{Errors}} - 1) + if ($Group->{IsNew}->[$ErrIndex]) { - if ($Group->{IsNew}->[$ErrIndex]) - { - $NewLineNos{$Group->{LineNos}->[$ErrIndex]} = 1; - } + $NewLineNos{$Group->{LineNos}->[$ErrIndex]} = 1; } } } } - my $GetCategory = $FileName =~ /\.err$/ ? \&GetErrorCategory : - $FileName =~ /\.report$/ ? \&GetReportLineCategory : + my $GetCategory = $LogName =~ /\.report$/ ? \&GetReportLineCategory : \&GetLogLineCategory; my $LineNo = 0; my $IsEmpty = 1; - if (open(my $LogFile, "<", $FileName)) + my $LineNo = 0; + if (open(my $LogFile, "<", "$Dir/$LogName")) { foreach my $Line (<$LogFile>) { @@ -390,7 +383,6 @@ sub GenerateFullLog($$$$;$) $Line =~ s/\s*$//; if ($IsEmpty) { - print $Header if (defined $Header); print ""; $IsEmpty = 0; } @@ -405,8 +397,32 @@ sub GenerateFullLog($$$$;$) } close($LogFile); } - print "\n" if (!$IsEmpty); + # And append the extra errors + foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) + { + my $Group = $LogInfo->{ErrGroups}->{$GroupName}; + # Extra groups don't have a line number + next if ($Group->{LineNo}); + + print "
$GroupName
\n"; + my $i = 0; + for my $i (0..@{$Group->{Errors}} - 1) + { + if ($IsEmpty) + { + print ""; + $IsEmpty = 0; + } + + my $Line = $Group->{Errors}->[$i]; + my $Category = $Group->{IsNew}->[$i] ? "new" : "error"; + my $Html = $self->escapeHTML($Line); + print "$Html\n"; + } + } + + print "\n" if (!$IsEmpty); return $IsEmpty; } @@ -486,48 +502,26 @@ EOF # Show this log in full, highlighting the important lines # - my $LogInfo; - my $LogFileName = "$TaskDir/$MoreInfo->{Full}"; - if ($MoreInfo->{Full} =~ /\.report$/) - { - $LogInfo = GetLogErrors($LogFileName); - if ($LogInfo->{ErrCount}) - { - # Identify new errors in test reports - my $RefReportPath = "$TaskDir/". $StepTask->GetRefReportName($MoreInfo->{Full}); - TagNewErrors($RefReportPath, $LogInfo); - } - } - my ($Action, $Url) = $self->GetMoreInfoLink($Key, GetLogLabel($MoreInfo->{Full}), "Full", $MoreInfo->{Full}); $Url = $self->CGI->escapeHTML($Url); my $HideLog = $Action eq "Hide" ? " ondblclick='HideLog(event, \"$Url\")'" : ""; - my $LogIsEmpty = $self->GenerateFullLog($LogFileName, $HideLog, $LogInfo); - my $EmptyDiag; + my $LogIsEmpty = $self->GenerateFullLog($TaskDir, $MoreInfo->{Full}, $HideLog); if ($LogIsEmpty) { if ($StepTask->Status eq "canceled") { - $EmptyDiag = "No log, task was canceled\n"; + print "No log, task was canceled\n"; } elsif ($StepTask->Status eq "skipped") { - $EmptyDiag = "No log, task skipped\n"; + print "No log, task skipped\n"; } else { print "Empty log\n"; - $LogIsEmpty = 0; } } - - # And append the associated extra errors - my $ErrHeader = $MoreInfo->{Full} =~ /\.report/ ? "report" : "task"; - $ErrHeader = "old $ErrHeader" if ($MoreInfo->{Full} =~ /^old_/); - $ErrHeader = "
". ucfirst($ErrHeader) ." errors
"; - my $ErrIsEmpty = $self->GenerateFullLog("$LogFileName.err", $HideLog, $LogInfo, $ErrHeader); - print $EmptyDiag if ($ErrIsEmpty and defined $EmptyDiag); } else { @@ -540,7 +534,7 @@ EOF foreach my $LogName (@{$MoreInfo->{Logs}}) { next if ($LogName =~ /^old_/); - my $LogInfo = GetLogErrors("$TaskDir/$LogName"); + my $LogInfo = LoadLogErrors("$TaskDir/$LogName"); next if (!$LogInfo->{ErrCount}); $LogInfos->{$LogName} = $LogInfo; } @@ -560,16 +554,9 @@ EOF } my $LogInfo = $LogInfos->{$LogName}; - if ($LogName =~ /\.report$/) - { - # For test reports try to identify the new errors - my $RefReportPath = "$TaskDir/". $StepTask->GetRefReportName($LogName); - TagNewErrors($RefReportPath, $LogInfo); - } - foreach my $GroupName (@{$LogInfo->{ErrGroupNames}}) { - print "
$GroupName
\n" if ($GroupName); + print "
$GroupName
\n"; print "
";
           my $ErrIndex = 0;

-- 
2.20.1