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 Signed-off-by: Francois Gouget fgouget@codeweavers.com ---
This is the big patch. As before it would be useful to keep a trace of what UpdateTaskLogs did in case something went wrong or just to check it worked as expected:
cd testbot/var && ../bin/UpdateTaskLogs --debug 2>&1 | tee UpdateTaskLogs.log
testbot/bin/Janitor.pl | 2 +- testbot/bin/UpdateTaskLogs | 136 +++++++------ testbot/bin/WineRunBuild.pl | 2 + testbot/bin/WineRunReconfig.pl | 2 + testbot/bin/WineRunTask.pl | 17 +- testbot/bin/WineRunWineTest.pl | 16 +- testbot/bin/WineSendLog.pl | 111 +++++++---- testbot/lib/WineTestBot/LogUtils.pm | 275 ++++++++++++++++++++++---- testbot/lib/WineTestBot/StepsTasks.pm | 7 - testbot/lib/WineTestBot/Tasks.pm | 4 + testbot/web/JobDetails.pl | 91 ++++----- 11 files changed, 445 insertions(+), 218 deletions(-)
diff --git a/testbot/bin/Janitor.pl b/testbot/bin/Janitor.pl index 888bebf3f2..0635b37880 100755 --- a/testbot/bin/Janitor.pl +++ b/testbot/bin/Janitor.pl @@ -315,7 +315,7 @@ if (opendir(my $dh, "$DataDir/latest")) my $TTL = $JobPurgeDays ? $JobPurgeDays - $Age : undef;
# Keep the regexp in sync with WineTestBot::Task::GetRefReportName() - 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 c6f7b753d3..d29b42afb2 100755 --- a/testbot/bin/UpdateTaskLogs +++ b/testbot/bin/UpdateTaskLogs @@ -4,7 +4,7 @@ # Updates or recreates the reference reports for the specified tasks and the # latest directory. # -# Copyright 2019 Francois Gouget +# Copyright 2019-2020 Francois Gouget # # This library is free software; you can redistribute it and/or # modify it under the terms of the GNU Lesser General Public @@ -146,7 +146,7 @@ if (defined $Usage) { print "Usage: $Name0 [--rebuild] [--log-only] [--debug] [--help] [JOBID [STEPNO [TASKNO]]]\n"; print "\n"; - print "Deletes, upgrades or recreates the reference reports and .err files for the specified tasks and the latest directory.\n"; + print "Deletes, upgrades or recreates the reference reports and .errors files for the specified tasks and the latest directory.\n"; print "\n"; print "Where:\n"; print " --delete Delete generated files of both the latest directory and the\n"; @@ -158,7 +158,7 @@ if (defined $Usage) print " reports are preserved. If these tasks don't have reference\n"; print " reports, an error is shown.\n"; print " Without this option only the missing reference reports and\n"; - print " .err files are added.\n"; + print " .errors files are added.\n"; print " JOBID STEPNO TASKNO Only the tasks matching the specified JOBID, STEPNO and\n"; print " TASKNO will be modified.\n"; print " --log-only Only print errors to the log. By default they also go to stderr.\n"; @@ -199,26 +199,15 @@ sub Delete($;$) return 1; }
-sub BuildErrFile($$$$) +sub BuildErrorsCache($$$$;$) { - my ($Dir, $ReportName, $IsWineTest, $TaskTimedOut) = @_; + my ($Dir, $LogName, $IsWineTest, $TaskTimedOut, $Task) = @_;
- my $TaskKey = Path2TaskKey($Dir); - - my $LogInfo = ParseWineTestReport("$Dir/$ReportName", $IsWineTest, $TaskTimedOut); - return "$TaskKey: $LogInfo->{BadLog}" if (defined $LogInfo->{BadLog}); - return undef if (!@{$LogInfo->{Extra}}); - - 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->{Extra}}); - close($Log); - return undef; - } - return "Unable to open '$TaskKey/$ReportName' for reading: $!"; + Debug(Path2TaskKey($Dir) .": Creating $LogName.errors\n"); + my $LogInfo = $LogName =~ /.report$/ ? + ParseWineTestReport("$Dir/$LogName", $IsWineTest, $TaskTimedOut) : + ParseTaskLog("$Dir/$LogName"); + return CreateLogErrorsCache($LogInfo, $Task); }
# Maps the reference report name to its full pathname. @@ -266,7 +255,8 @@ sub MoveRefReport($$;$) my ($RefDir, $RefName, $NewDir) = @_;
my $RefPath = "$RefDir/$RefName"; - return Delete("$RefPath.err", "orphaned") if (!-f $RefPath); + my $Rc = Delete("$RefPath.err"); + return $Rc if (!-f $RefPath);
$NewDir ||= $RefDir; my $NewName = $RefName; @@ -280,14 +270,11 @@ sub MoveRefReport($$;$) my $NewPath = "$NewDir/$NewName"; return 0 if ($RefPath eq $NewPath);
- my $Rc = 0; my $TaskKey = Path2TaskKey($NewDir); if (-f $NewPath and -M $NewPath <= -M $RefPath) { # A WineTest job has probably completed after the upgrade already - $Rc += Delete($RefPath); - $Rc += Delete("$RefPath.err"); - return $Rc; + return Delete($RefPath); }
if (-f $NewPath) @@ -297,16 +284,14 @@ sub MoveRefReport($$;$) }
my $RelRefDir = ($RefDir eq $NewDir) ? "" : "../"; - Debug("$TaskKey: $RelRefDir$RefName* -> $NewName\n"); - foreach my $Suffix ("", ".err") + Debug("$TaskKey: $RelRefDir$RefName -> $NewName\n"); + if (!rename($RefPath, $NewPath)) { - next if (!-f "$RefPath$Suffix"); - next if (rename("$RefPath$Suffix", "$NewPath$Suffix")); - Error "Could not move '$RefName$Suffix' to '$NewName$Suffix' for $TaskKey: $!\n"; - $Rc = 1; + Error "Could not move '$RefName' to '$NewName' for $TaskKey: $!\n"; + return 1; }
- return $Rc; + return 0; }
sub ProcessTaskLogs($$$) @@ -367,7 +352,11 @@ 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"; - $Rc += Delete($TestBotLog) if (-z $TestBotLog); + if (-z $TestBotLog and (!-f "$TestBotLog.errors" or -z _)) + { + $Rc += Delete($TestBotLog); + $Rc += Delete("$TestBotLog.errors"); + } }
if (($OptDelete or $OptRebuild) and !$CollectOnly) @@ -379,13 +368,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 (!$OptDelete and !-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($TaskDir, $RefReportName, 1, 0); + my $ErrMessage = BuildErrorsCache($TaskDir, $RefReportName, 1, 0); if (defined $ErrMessage) { Error "$ErrMessage\n"; @@ -399,8 +388,16 @@ sub ProcessTaskLogs($$$) } $Rc += Delete($RefReportPath); $Rc += Delete("$RefReportPath.err"); + $Rc += Delete("$RefReportPath.errors"); $Rc += Delete("$TaskDir/$ReportName.err"); } + + # And clean up the files derived from the task's logs + foreach my $LogName (@{GetLogFileNames($TaskDir, "+old")}) + { + $Rc += Delete("$TaskDir/$LogName.err"); + $Rc += Delete("$TaskDir/$LogName.errors"); + } }
if (!$OptDelete and !$CollectOnly and $Task->Status eq "completed") @@ -409,7 +406,9 @@ sub ProcessTaskLogs($$$) foreach my $ReportName (@{GetLogFileNames($TaskDir)}) { next if ($ReportName !~ /.report$/); + my $RefReportName = $Task->GetRefReportName($ReportName); + $Rc += Delete("$TaskDir/$RefReportName.err"); next if (-f "$TaskDir/$RefReportName");
my $LatestReportPath = $LatestReports{$RefReportName}; @@ -421,7 +420,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 @@ -433,22 +432,42 @@ sub ProcessTaskLogs($$$) } } } + }
- # And (re)build the .err files - if ($Task->Status !~ /^(?:queued|running)$/) + if (!$OptDelete and !$CollectOnly and $Task->Status !~ /^(?:queued|running)$/) + { + # And (re)build the .errors files, even if Status != 'completed' for + # task.log and testbot.log. + my ($IsWineTest, $TaskTimedOut); + if ($Task->Started and $Task->Ended) { - 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")}) + { + $Rc += Delete("$TaskDir/$LogName.err"); + if ($LogName =~ /.report$/) { - my $Duration = $Task->Ended - $Task->Started; - $TaskTimedOut = $Duration > $Task->Timeout; - $IsWineTest = ($Step->Type eq "patch" or $Step->Type eq "suite"); + # First for the reference report if any + 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; + } + } } - foreach my $ReportName (@{GetLogFileNames($TaskDir)}) + + # Then for the report / log itself + if (!-f "$TaskDir/$LogName.errors") { - next if ($ReportName !~ /.report$/); - next if (-f "$TaskDir/$ReportName.err"); - my $ErrMessage = BuildErrFile($TaskDir, $ReportName, $IsWineTest, $TaskTimedOut); + my $ErrMessage = BuildErrorsCache($TaskDir, $LogName, $IsWineTest, $TaskTimedOut, $Task); if (defined $ErrMessage) { Error "$ErrMessage\n"; @@ -500,34 +519,35 @@ sub ProcessLatestReports() } else { - # MoveRefReport() also renames .err files + # MoveRefReport() also deletes .err files $Rc += MoveRefReport("$DataDir/latest", $RefReportName); } }
# Then perform cleanups and rebuild missing files - foreach my $LatestReportPath (glob("$LatestGlob $LatestGlob.err")) + foreach my $LatestReportPath (glob("$LatestGlob $LatestGlob.errors")) { my $RefReportName = basename($LatestReportPath); # Keep the regexp in sync with WineTestBot::Task::GetRefReportName() - next if ($RefReportName !~ /^([a-zA-Z0-9_]+-job[0-9]+-[a-zA-Z0-9_]+.report)(?:.err)?$/); + next if ($RefReportName !~ /^([a-zA-Z0-9_]+-job[0-9]+-[a-zA-Z0-9_]+.report)(?:.errors)?$/); $RefReportName = $1; # untaint $LatestReportPath = "$DataDir/latest/$RefReportName"; + $Rc += Delete("$LatestReportPath.err");
if ($OptDelete or $OptRebuild) { # These can be rebuilt from the task reports $Rc += Delete($LatestReportPath); - $Rc += Delete("$LatestReportPath.err"); + $Rc += Delete("$LatestReportPath.errors"); } elsif (!-f $LatestReportPath) { - $Rc += Delete("$LatestReportPath.err", "orphaned"); + $Rc += Delete("$LatestReportPath.errors", "orphaned"); } - elsif (!-f "$LatestReportPath.err") + elsif (!-f "$LatestReportPath.errors") { - # Build the missing .err file - my $ErrMessage = BuildErrFile("$DataDir/latest", $RefReportName, 1, 0); + # Build the missing .errors file + my $ErrMessage = BuildErrorsCache("$DataDir/latest", $RefReportName, 1, 0); if (defined $ErrMessage) { Error "$ErrMessage\n"; diff --git a/testbot/bin/WineRunBuild.pl b/testbot/bin/WineRunBuild.pl index 45288af95a..e7a90aa4a3 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 83c26ccd3c..74f618151f 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 59975c3df9..f55fa9f706 100755 --- a/testbot/bin/WineRunTask.pl +++ b/testbot/bin/WineRunTask.pl @@ -534,7 +534,13 @@ 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"); + my $ErrMessage = CreateLogErrorsCache($LogInfo); + LogTaskError("$ErrMessage\n") if (defined $ErrMessage); +} +elsif (!defined $TAError) { $TAError = "An error occurred while retrieving the task log: ". $TA->GetLastError(); } @@ -561,13 +567,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 9d54745966..c35d6c0ae8 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 e0cd585b11..23930993cb 100755 --- a/testbot/bin/WineSendLog.pl +++ b/testbot/bin/WineSendLog.pl @@ -78,6 +78,54 @@ 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 = $LogName =~ /.report$/ ? + ParseWineTestReport("$TaskDir/$LogName", $IsWineTest, $TaskTimedOut) : + 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 # @@ -98,27 +146,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}}); } }
@@ -208,12 +257,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}}) { @@ -292,35 +342,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"; } @@ -511,6 +543,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 66359a9dc7..9bde76c6c6 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<GetLogErrors()>
-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 @@ -844,37 +844,177 @@ sub GetLogErrors($) _AddLogError($LogInfo, $Group, $LogInfo->{BadLog}); }
- if (open(my $LogFile, "<", "$LogPath.err")) + return $LogInfo; +} + + +# +# Log errors caching [Part 1] +# + +=pod +=over 12 + +=item C<LoadLogErrors()> + +Loads the specified log errors file. + +The file contains two types of lines: +* GroupName lines + <GroupName> + Where <GroupName> 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 + <Space> <New> <SrcLineNo> <Error> + Where: + - <Space> is a space, as well as the spaces in the line above. + - <New> is either 'n' for new errors, or 'o' for old ones. + - <SrcLineNo> 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. + - <Error> is the error message. + +Returns the errors in the same format as TagNewErrors(). + +=back +=cut + +sub LoadLogErrors($) +{ + my ($LogPath) = @_; + + my $LogName = basename($LogPath); + my $LogInfo = { + LogName => $LogName, + LogPath => $LogPath, + + ErrGroupNames => [], + ErrGroups => {}, + }; + $LogPath .= ".errors"; + + my $ErrorsFile; + if (!open($ErrorsFile, "<", $LogPath)) + { + $LogInfo->{BadLog} = "Unable to open '$LogName' for reading: $!"; + return $LogInfo; + } + + my $CurGroup; + 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") - { - $LogInfo->{BadLog} ||= "Could not open '$LogName.err' for reading: $!"; - my $Group = _AddLogGroup($LogInfo, "TestBot errors"); - _AddLogError($LogInfo, $Group, $LogInfo->{BadLog}); + elsif ($Type eq "g") + { + $CurGroup = _AddLogGroup($LogInfo, $Value, $Property); + } + elsif (!$CurGroup) + { + $LogInfo->{BadLog} = "Got a $Type line with no group"; + last; + } + elsif ($Type eq "o") + { + _AddLogError($LogInfo, $CurGroup, $Value, $Property); + } + elsif ($Type eq "n") + { + _AddLogError($LogInfo, $CurGroup, $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 <LogName>.errors. + +The file contains lines of the form: + <type> <value1> <value2> + +The values depend on the <type> of the line. <type> and <value1> must not +contain spaces while <value2> runs to the end of the line. More specifically +the line formats are: +=over + +=item p <name> <value> +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 <lineno> <groupname> +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 <lineno> <line> +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 <lineno> <line> +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 @@ -902,6 +1042,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
@@ -980,7 +1132,7 @@ sub TagNewErrors($$)
return if (!$LogInfo->{ErrCount});
- my $RefInfo = GetLogErrors($RefLogPath); + my $RefInfo = LoadLogErrors($RefLogPath); if (defined $RefInfo->{BadLog}) { # Save the BadLog error but do not tag the errors as new: this is up to @@ -1039,6 +1191,47 @@ sub TagNewErrors($$) }
+# +# Log errors caching [Part 2] +# + +sub CreateLogErrorsCache($;$) +{ + my ($ParsedInfo, $Task) = @_; + + my $LogInfo = GetLogErrors($ParsedInfo->{LogPath}); + + # Store ParseWineTestReport()'s extra errors into their own group + my $ExtraCount = $ParsedInfo->{Extra} ? @{$ParsedInfo->{Extra}} : 0; + if ($ExtraCount) + { + my $Group = _AddLogGroup($LogInfo, "Report validation errors"); + $Group->{Errors} = $ParsedInfo->{Extra}; + my @LineNos = (0) x $ExtraCount; + $Group->{LineNos} = @LineNos; + $LogInfo->{ErrCount} += $ExtraCount; + } + + return $LogInfo->{BadLog} if (defined $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 # @@ -1067,7 +1260,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");
@@ -1087,7 +1280,7 @@ 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. next if (!-f "$SrcReportPath$Suffix"); diff --git a/testbot/lib/WineTestBot/StepsTasks.pm b/testbot/lib/WineTestBot/StepsTasks.pm index f65e6a6327..463f15078a 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 541b5558e3..f8b91d1c31 100644 --- a/testbot/lib/WineTestBot/Tasks.pm +++ b/testbot/lib/WineTestBot/Tasks.pm @@ -70,6 +70,7 @@ our @ISA = qw(WineTestBot::WineTestBotItem); use File::Path; use ObjectModel::BackEnd; use WineTestBot::Config; +use WineTestBot::LogUtils; use WineTestBot::Missions;
@@ -172,6 +173,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 3dce91595d..ccf3410f5b 100644 --- a/testbot/web/JobDetails.pl +++ b/testbot/web/JobDetails.pl @@ -346,43 +346,36 @@ sub GenerateMoreInfoLink($$$$;$$) print "<div class='TaskMoreInfoLink'>$Html</div>\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 "<pre$HideLog><code>"; $IsEmpty = 0; } @@ -405,8 +397,32 @@ sub GenerateFullLog($$$$;$) } close($LogFile); } - print "</code></pre>\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 "<div class='LogDllName'>$GroupName</div>\n"; + my $i = 0; + for my $i (0..@{$Group->{Errors}} - 1) + { + if ($IsEmpty) + { + print "<pre$HideLog><code>"; + $IsEmpty = 0; + } + + my $Line = $Group->{Errors}->[$i]; + my $Category = $Group->{IsNew}->[$i] ? "new" : "error"; + my $Html = $self->escapeHTML($Line); + print "<span class='log-$Category'>$Html</span>\n"; + } + } + + print "</code></pre>\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 = "<div class='HrTitle'>". ucfirst($ErrHeader) ." errors<div class='HrLine'></div></div>"; - 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,13 +554,6 @@ 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 "<div class='LogDllName'>$GroupName</div>\n" if ($GroupName);
It makes sense to retry if retrieving Task.log fails because it may be caused by a temporary network issue. But ParseTaskLog() would only fail if there is a bug or the TestBot was set up wrong. Since retrying would not help it is better to simply report the error.
Signed-off-by: Francois Gouget fgouget@codeweavers.com --- testbot/bin/WineRunBuild.pl | 2 +- testbot/bin/WineRunReconfig.pl | 2 +- testbot/bin/WineRunWineTest.pl | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-)
diff --git a/testbot/bin/WineRunBuild.pl b/testbot/bin/WineRunBuild.pl index e7a90aa4a3..2764ffc921 100755 --- a/testbot/bin/WineRunBuild.pl +++ b/testbot/bin/WineRunBuild.pl @@ -435,7 +435,7 @@ if ($TA->GetFile("Build.log", "$TaskDir/task.log")) } elsif (defined $LogInfo->{BadLog}) { - FatalError("$LogInfo->{BadLog}\n", "retry"); + # Let CreateLogErrorsCache() report it } else { diff --git a/testbot/bin/WineRunReconfig.pl b/testbot/bin/WineRunReconfig.pl index 74f618151f..13557c1007 100755 --- a/testbot/bin/WineRunReconfig.pl +++ b/testbot/bin/WineRunReconfig.pl @@ -430,7 +430,7 @@ if ($TA->GetFile("Reconfig.log", "$TaskDir/task.log")) } elsif (defined $LogInfo->{BadLog}) { - FatalError("$LogInfo->{BadLog}\n", "retry"); + # Let CreateLogErrorsCache() report it } else { diff --git a/testbot/bin/WineRunWineTest.pl b/testbot/bin/WineRunWineTest.pl index c35d6c0ae8..f6e6c977d4 100755 --- a/testbot/bin/WineRunWineTest.pl +++ b/testbot/bin/WineRunWineTest.pl @@ -525,7 +525,7 @@ if ($TA->GetFile("Task.log", "$TaskDir/task.log")) } elsif (defined $LogInfo->{BadLog}) { - FatalError("$LogInfo->{BadLog}\n", "retry"); + # Let CreateLogErrorsCache() report it } elsif ($LogInfo->{Type} eq "build") {
-
Francois Gouget