From f7462389b6b3d89329468ff104419e80e91a15ae Mon Sep 17 00:00:00 2001 From: Daniel Hilst <392820+dhilst@users.noreply.github.com> Date: Fri, 4 Sep 2026 16:39:33 -0300 Subject: [PATCH] fix(xcat-core): xcattest reports only the check where a case stopped A failing case named one failed check and no result at all for the checks after it, although the commands of the case kept running. The first [Failed] line was read as the cause of the failure three times this week, and each time the real fault was a later check: a riscv64 cell reported a makedns check 160 lines before rpower could not start the domain. run_case in xCAT-test/xcattest used one variable, $failflag, for two facts: the result of the case, and the result of the check being reported. Every branch read $failflag to decide whether to print [Pass] or [Failed], so a check that ran after a failed one always read as failed. The guard "last if ($failflag)" at the top of the check loop hid that, and hid every later check with it. The result of a check is now $checkfail, set and read inside one iteration. A continue block carries it into $failflag, which keeps the result of the case. The guard and the per-branch "last" statements are gone, so each check reports what it found. The output ~~ branch no longer clears $failflag on a match, which without the guard would have turned a failed case into a passing one. xCAT-test/unit/xcattest_report_every_check.t runs the harness over a fixture case and asserts on the CHECK lines it writes. Without this change it reports two of four checks, and one of two failed checks. A case whose checks all pass logs the same text before and after: no truncation could happen while $failflag stayed 0. Signed-off-by: Daniel Hilst <392820+dhilst@users.noreply.github.com> --- xCAT-test/unit/xcattest_report_every_check.t | 142 +++++++++++++++++++ xCAT-test/xcattest | 31 ++-- 2 files changed, 159 insertions(+), 14 deletions(-) create mode 100644 xCAT-test/unit/xcattest_report_every_check.t diff --git a/xCAT-test/unit/xcattest_report_every_check.t b/xCAT-test/unit/xcattest_report_every_check.t new file mode 100644 index 000000000..4479de6ab --- /dev/null +++ b/xCAT-test/unit/xcattest_report_every_check.t @@ -0,0 +1,142 @@ +#!/usr/bin/env perl +use strict; +use warnings; + +use FindBin; +use File::Copy qw(copy); +use File::Path qw(make_path); +use File::Temp qw(tempdir); +use Test::More; + +my $program = "$FindBin::Bin/../xcattest"; +BAIL_OUT("xcattest is not at $program") unless -f $program; + +#--- +=head3 run_harness + + Descriptions: Run xcattest over one fixture case file and return its log lines. + Arguments: + $case_text - the content of the fixture case file + @names - the case names to run + Returns: a reference to the array of log lines, and the failed-cases report lines +=cut + +#--- +sub run_harness { + my ($case_text, @names) = @_; + + # xcattest derives its result directory from the location of the program, so the copy + # under the scratch tree keeps every file the run writes inside that tree. + my $root = tempdir(CLEANUP => 1); + make_path("$root/bin", "$root/cases"); + copy($program, "$root/bin/xcattest") or BAIL_OUT("copy xcattest: $!"); + chmod 0755, "$root/bin/xcattest"; + + open(my $case_fh, '>', "$root/cases/fixture") or BAIL_OUT("write the fixture case: $!"); + print $case_fh $case_text; + close($case_fh) or BAIL_OUT("close the fixture case: $!"); + + local $ENV{XCATTEST_CASEDIR} = "$root/cases"; + system($^X, "$root/bin/xcattest", '-q', '-t', join(',', @names)); + + my $slurp = sub { + my ($path) = @_; + open(my $fh, '<', $path) or BAIL_OUT("open $path: $!"); + my @lines = <$fh>; + close($fh) or BAIL_OUT("close $path: $!"); + chomp(@lines); + return @lines; + }; + + my ($log) = glob("$root/share/xcat/tools/autotest/result/xcattest.log.*"); + BAIL_OUT("the harness wrote no running log under $root") unless $log; + my ($failed) = glob("$root/share/xcat/tools/autotest/result/failedcases.*"); + BAIL_OUT("the harness wrote no failed-cases report under $root") unless $failed; + + return ([ $slurp->($log) ], [ $slurp->($failed) ]); +} + +#--- +=head3 reported_checks + + Descriptions: Select the check results the harness reported. + Arguments: + $lines - a reference to the array of log lines + Returns: a reference to the array of CHECK lines, in the order they were reported +=cut + +#--- +sub reported_checks { + my ($lines) = @_; + return [ grep { /^CHECK:/ } @{$lines} ]; +} + +# The second command fails its first check. The check after it on the same command, and the +# checks of every command after it, describe the same run and must report their own result. +my $mixed = <<'CASE'; +start:mixedchecks +description:a failed check between checks that pass +cmd:echo alpha +check:rc==0 +cmd:echo beta +check:rc!=0 +check:output=~beta +cmd:echo gamma +check:output=~gamma +end +CASE + +my ($log, $failed) = run_harness($mixed, 'mixedchecks'); + +is_deeply(reported_checks($log), + [ "CHECK:rc == 0\t[Pass]", + "CHECK:rc != 0\t[Failed]", + "CHECK:output =~ beta\t[Pass]", + "CHECK:output =~ gamma\t[Pass]" ], + 'every check reports its own result, and a failed check does not silence the checks after it'); + +is_deeply(reported_checks($failed), reported_checks($log), + 'the failed-cases report carries the same check results as the running log'); + +ok(scalar(grep { /^------END::mixedchecks::Failed::/ } @{$log}), + 'a check that passes after a failed check does not make the case pass'); + +# A case that fails more than one check names every one of them. +my $twofails = <<'CASE'; +start:twofailedchecks +description:two commands, each with a check that fails +cmd:echo one +check:rc!=0 +cmd:echo two +check:rc!=0 +end +CASE + +($log, $failed) = run_harness($twofails, 'twofailedchecks'); + +is_deeply(reported_checks($log), + [ "CHECK:rc != 0\t[Failed]", "CHECK:rc != 0\t[Failed]" ], + 'both failed checks are reported, not just the first'); + +# A case where every check passes is unchanged. +my $allpass = <<'CASE'; +start:allcheckspass +description:every check passes +cmd:echo alpha +check:rc==0 +check:output=~alpha +cmd:echo beta +check:output=~beta +end +CASE + +($log, $failed) = run_harness($allpass, 'allcheckspass'); + +is_deeply(reported_checks($log), + [ "CHECK:rc == 0\t[Pass]", "CHECK:output =~ alpha\t[Pass]", "CHECK:output =~ beta\t[Pass]" ], + 'a case whose checks all pass reports every check'); + +ok(scalar(grep { /^------END::allcheckspass::Passed::/ } @{$log}), + 'a case whose checks all pass still reports Passed'); + +done_testing(); diff --git a/xCAT-test/xcattest b/xCAT-test/xcattest index bc89b4532..835788c03 100755 --- a/xCAT-test/xcattest +++ b/xCAT-test/xcattest @@ -1417,8 +1417,12 @@ sub run_case { log_this($running_log_fd, ("ElapsedTime:$diffduration sec", "RETURN rc = $rc", "OUTPUT:", @output)); push(@caselog, ("ElapsedTime:$diffduration sec", "RETURN rc = $rc", "OUTPUT:", @output)); + # $checkfail is the result of this check, $failflag the result of the case. They + # were one variable, so a failed check made every later check read as failed, and + # the guard that hid that also hid the checks (issue #76). + my $checkfail = 0; foreach my $check (@{ $cases_ref->[ $case_name_index_map_ref->{$case} ]->{check}->[$j] }) { - last if ($failflag); + $checkfail = 0; if ($check =~ /rc\s*([=!]+)\s*(\d+)/) { my $lvalue = $rc; @@ -1426,12 +1430,11 @@ sub run_case { my $rvalue = $2; if ((($op eq '!=') && ($lvalue == $rvalue)) || (($op eq '==') && ($lvalue != $rvalue))) { - $failflag = 1; + $checkfail = 1; } - if ($failflag) { + if ($checkfail) { log_this($running_log_fd, "CHECK:rc $op $rvalue\t[Failed]"); push(@caselog, "CHECK:rc $op $rvalue\t[Failed]"); - last; } else { log_this($running_log_fd, "CHECK:rc $op $rvalue\t[Pass]"); push(@caselog, "CHECK:rc $op $rvalue\t[Pass]"); @@ -1446,17 +1449,16 @@ sub run_case { || (($op eq '!~') && ($lvalue =~ /$rvalue/)) || (($op eq '==') && ($lvalue ne $rvalue)) || (($op eq '!=') && ($lvalue eq $rvalue))) { - $failflag = 1; + $checkfail = 1; } elsif (($op ne '=~') && ($op ne '!~') && ($op ne '==') && ($op ne '!=')) { - $failflag = 1; + $checkfail = 1; log_this($running_log_fd, "CHECK:output unrecognized operator: $op\t[Failed]"); push(@caselog, "CHECK:output unrecognized operator: $op\t[Failed]"); - last; + next; } - if ($failflag) { + if ($checkfail) { log_this($running_log_fd, "CHECK:output $op $rvalue\t[Failed]"); push(@caselog, "CHECK:output $op $rvalue\t[Failed]"); - last; } else { log_this($running_log_fd, "CHECK:output $op $rvalue\t[Pass]"); push(@caselog, "CHECK:output $op $rvalue\t[Pass]"); @@ -1464,7 +1466,7 @@ sub run_case { } elsif ($check =~ /output\s*~~\s*(\S.*)/) { my $op = "~~"; - #my $failflag = 1; + # This operator only sets $checkfail to 0, so the check always reports Pass. my $rvalue = $1; $rvalue = getfunc($rvalue); @@ -1481,7 +1483,7 @@ sub run_case { my $min = $num * 0.9; $line =~ /.*:.*: (\d+) /; if ($1 < $max && $1 > $min) { - $failflag = 0; + $checkfail = 0; last; } } else { @@ -1489,19 +1491,20 @@ sub run_case { } } } - if ($failflag) { + if ($checkfail) { log_this($running_log_fd, "CHECK:output $op $rvalue\t[Failed]"); push(@caselog, "CHECK:output $op $rvalue\t[Failed]"); - last; } else { log_this($running_log_fd, "CHECK:output $op $rvalue\t[Pass]"); push(@caselog, "CHECK:output $op $rvalue\t[Pass]"); } } else { - $failflag = 1; + $checkfail = 1; log_this($running_log_fd, "Unrecognized testcase syntax: CHECK:$check\t[Failed]"); push(@caselog, "Unrecognized testcase syntax: CHECK:$check\t[Failed]"); } + } continue { + $failflag = 1 if ($checkfail); } foreach my $cmdcheck (@{ $cases_ref->[ $case_name_index_map_ref->{$case} ]->{cmdcheck}->[$j] }) { if ($cmdcheck) {