mariadb/mysql-test/lib/mtr_report.pm
Vladislav Vaintroub f197f9a527 MDEV-32387 Windows - mtr output on is messed up with large MTR_PARALLEL.
Windows C runtime does not implement line buffering mode for stdio.

This sometimes makes output from different tests interleaved in MTR
MTR relies on this buffering (lines won't  output until "\n") to correctly
work in parallel scenarios.

Implement do-it-yourself line buffering on Windows, to workaround.
2023-10-10 20:53:00 +02:00

773 lines
20 KiB
Perl

# -*- cperl -*-
# Copyright (c) 2004, 2011, Oracle and/or its affiliates.
# Copyright (c) 2009-2011, Monty Program Ab
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation; version 2 of the License.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software
# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1335 USA
# This is a library file used by the Perl version of mysql-test-run,
# and is part of the translation of the Bourne shell script with the
# same name.
package mtr_report;
use strict;
use Sys::Hostname;
use base qw(Exporter);
our @EXPORT= qw(report_option mtr_print_line mtr_print_thick_line
mtr_print_header mtr_report mtr_report_stats
mtr_warning mtr_error mtr_debug mtr_verbose mtr_verbose2
mtr_verbose_restart mtr_report_test_passed
mtr_report_test_skipped mtr_print
mtr_report_test isotime);
use mtr_match;
use My::Platform;
use POSIX qw[ _exit ];
use IO::Handle qw[ flush ];
use mtr_results;
use Term::ANSIColor;
use English;
my $tot_real_time= 0;
my $tests_done= 0;
my $tests_failed= 0;
our $timestamp= 0;
our $timediff= 0;
our $name;
our $verbose;
# TODO: no option for that? Why is it different from $verbose?
our $verbose_restart= 0;
our $timer= 1;
our $tests_total;
my %color_map = qw/pass green
retry-pass green
fail red
retry-fail red
disabled bright_black
skipped yellow
reset reset/;
my $set_titlebar;
my $set_color= sub { };
if (-t STDOUT) {
if (IS_WINDOWS) {
eval {
require Win32::Console;
$set_titlebar = sub { &Win32::Console::Title($_[0]);};
}
} elsif ($ENV{TERM} =~ /xterm/) {
$set_titlebar = sub { syswrite STDOUT, "\e]0;$_[0]\a"; };
$set_color = sub { syswrite STDOUT, color($color_map{$_[0]}); }
}
}
# On Windows, stdio does not support line buffering
# This can make MTR output from multiple forked processes interleaved, messed up.
# Below is DYI stdout line buffering.
my $out_line="";
# Flush buffered line
sub flush_out {
print $out_line;
$out_line = "";
}
# Print to stdout
sub print_out {
if(IS_WIN32PERL) {
$out_line .= $_[0];
# Flush buffered output on new lines.
if (rindex($_[0], "\n") != -1) {
flush_out();
}
} else {
print($_[0]);
}
}
sub titlebar_stat($) {
sub time_format($) {
sprintf '%d:%02d:%02d', $_[0]/3600, ($_[0]/60)%60, $_[0]%60;
}
$tests_done++;
$tests_failed++ if $_[0] =~ /fail/;
$tests_total++ if $_[0] =~ /retry/;
my $spent = time - $BASETIME;
my $left = $tests_total - $tests_done;
&$set_titlebar(sprintf "mtr: spent %s on %d tests. %s (%d tests) left, %d failed",
time_format($spent), $tests_done,
time_format($spent/$tests_done * $left), $left, $tests_failed);
}
sub report_option {
my ($opt, $value)= @_;
# Evaluate $opt as string to use "Getopt::Long::Callback legacy API"
my $opt_name = "$opt";
# Convert - to _ in option name
$opt_name =~ s/-/_/g;
no strict 'refs';
${$opt_name}= $value;
}
sub _name {
return $name ? $name." " : undef;
}
sub _mtr_report_test_name ($) {
my $tinfo= shift;
my $tname= $tinfo->fullname();
return unless defined $verbose;
print_out _name(). _timestamp();
print_out (sprintf "%-40s ", $tname);
my $worker = $tinfo->{worker};
print_out "w$worker " if defined $worker;
return $tname;
}
sub mtr_report_test_skipped ($) {
my ($tinfo)= @_;
$tinfo->{'result'}= 'MTR_RES_SKIPPED';
mtr_report_test($tinfo);
}
sub mtr_report_test_passed ($) {
my ($tinfo)= @_;
# Save the timer value
my $timer_str= "";
if ( $timer and -f "$::opt_vardir/log/timer" )
{
$timer_str= ::mtr_fromfile("$::opt_vardir/log/timer");
$tinfo->{timer}= $timer_str;
resfile_test_info('duration', $timer_str) if $::opt_resfile;
}
# Big warning if status already set
if ( $tinfo->{'result'} ){
mtr_warning("mtr_report_test_passed: Test result",
"already set to '", $tinfo->{'result'}, ",");
}
$tinfo->{'result'}= 'MTR_RES_PASSED';
mtr_report_test($tinfo);
resfile_global("endtime ", isotime (time));
}
sub mtr_report_test ($) {
my ($tinfo)= @_;
my $test_name = _mtr_report_test_name($tinfo);
my $comment= $tinfo->{'comment'};
my $logfile= $tinfo->{'logfile'};
my $warnings= $tinfo->{'warnings'};
my $result= $tinfo->{'result'};
my $retry= $tinfo->{'retries'} ? "retry-" : $tinfo->{'repeat'} ? "$tinfo->{'repeat'} " : "";
if ($result eq 'MTR_RES_FAILED'){
my $timest = format_time();
my $fail = "fail";
if ( @$::experimental_test_cases )
{
# Find out if this test case is an experimental one, so we can treat
# the failure as an expected failure instead of a regression.
for my $exp ( @$::experimental_test_cases ) {
# Include pattern match for combinations
if ( $exp ne $test_name && $test_name !~ /^$exp / ) {
# if the expression is not the name of this test case, but has
# an asterisk at the end, determine if the characters up to
# but excluding the asterisk are the same
if ( $exp ne "" && substr($exp, -1, 1) eq "*" ) {
my $nexp = substr($exp, 0, length($exp) - 1);
if ( substr($test_name, 0, length($nexp)) ne $nexp ) {
# no match, try next entry
next;
}
# if yes, fall through to set the exp-fail status
} else {
# no match, try next entry
next;
}
}
$fail = "exp-fail";
$tinfo->{exp_fail}= 1;
last;
}
}
if ( $warnings )
{
mtr_report("[ $retry$fail ] Found warnings/errors in server log file!");
mtr_report(" Test ended at $timest");
mtr_report($warnings);
return;
}
my $timeout= $tinfo->{'timeout'};
if ( $timeout )
{
mtr_report("[ $retry$fail ] timeout after $timeout seconds");
mtr_report(" Test ended at $timest");
mtr_report("\n$tinfo->{'comment'}");
return;
}
else
{
mtr_report("[ $retry$fail ]\n Test ended at $timest");
}
if ( $logfile )
{
# Test failure was detected by test tool and its report
# about what failed has been saved to file. Display the report.
mtr_report("\n$logfile\n");
}
if ( $comment )
{
# The test failure has been detected by mysql-test-run.pl
# when starting the servers or due to other error, the reason for
# failing the test is saved in "comment"
mtr_report("\n$comment\n");
}
if ( !$logfile and !$comment )
{
# Neither this script or the test tool has recorded info
# about why the test has failed. Should be debugged.
mtr_report("\nUnknown result, neither 'comment' or 'logfile' set");
}
}
elsif ($result eq 'MTR_RES_SKIPPED')
{
if ( $tinfo->{'disable'} )
{
mtr_report("[ disabled ] $comment");
}
elsif ( $comment )
{
mtr_report("[ skipped ] $comment");
}
else
{
mtr_report("[ skipped ]");
}
if ( $tinfo->{'warnings'} )
{
mtr_report($tinfo->{'warnings'});
}
}
elsif ($result eq 'MTR_RES_PASSED')
{
my $timer_str= $tinfo->{timer} || "";
$tot_real_time += ($timer_str/1000);
mtr_report("[ ${retry}pass ] ", sprintf("%5s", $timer_str));
# Show any problems check-testcase found
if ( defined $tinfo->{'check'} )
{
mtr_report($tinfo->{'check'});
}
}
}
sub mtr_report_stats ($$$$) {
my $prefix= shift;
my $fail= shift;
my $tests= shift;
my $extra_warnings= shift;
# ----------------------------------------------------------------------
# Find out how we where doing
# ----------------------------------------------------------------------
my $tot_disabled = 0;
my $tot_skipped= 0;
my $tot_skipdetect= 0;
my $tot_passed= 0;
my $tot_failed= 0;
my $tot_tests= 0;
my $tot_restarts= 0;
my $found_problems= 0;
foreach my $tinfo (@$tests)
{
if ( $tinfo->{failures} )
{
# Test has failed at least one time
$tot_tests++;
$tot_failed++;
}
elsif ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' )
{
# Test was skipped (disabled not counted)
$tot_skipped++ unless $tinfo->{'disable'};
$tot_disabled++ if $tinfo->{'disable'};
$tot_skipdetect++ if $tinfo->{'skip_detected_by_test'};
}
elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' )
{
# Test passed
$tot_tests++;
$tot_passed++;
}
if ( $tinfo->{'restarted'} )
{
# Servers was restarted
$tot_restarts++;
}
# Add counts for repeated runs, if any.
# Note that the last run has already been counted above.
my $num_repeat = $tinfo->{'repeat'} - 1;
if ( $num_repeat > 0 )
{
$tot_tests += $num_repeat;
my $rep_failed = $tinfo->{'rep_failures'} || 0;
$tot_failed += $rep_failed;
$tot_passed += $num_repeat - $rep_failed;
}
# Look for warnings produced by mysqltest
my $base_file= mtr_match_extension($tinfo->{'result_file'},
"result"); # Trim extension
my $warning_file= "$base_file.warnings";
if ( -f $warning_file )
{
$found_problems= 1;
mtr_warning("Check myqltest warnings in '$warning_file'");
}
}
# ----------------------------------------------------------------------
# Print out a summary report to screen
# ----------------------------------------------------------------------
print "The servers were restarted $tot_restarts times\n";
if ( $timer )
{
mtr_report("Spent", sprintf("%.3f", $tot_real_time),"of",
time - $BASETIME, "seconds executing testcases");
}
resfile_global("duration", time - $BASETIME) if $::opt_resfile;
my $warnlog= "$::opt_vardir/log/warnings";
if ( ! $::glob_use_running_server && !$::opt_extern && -f $warnlog)
{
mtr_warning("Got errors/warnings while running tests, please examine",
"'$warnlog' for details.");
}
print "\n";
# Print a list of check_testcases that failed(if any)
if ( $::opt_check_testcases )
{
my %check_testcases;
foreach my $tinfo (@$tests)
{
if ( defined $tinfo->{'check_testcase_failed'} )
{
$check_testcases{$tinfo->{'name'}}= 1;
}
}
if ( keys %check_testcases )
{
print "Check of testcase failed for: ";
print join(" ", keys %check_testcases);
print "\n\n";
}
}
# Print summary line prefix
print "$prefix: ";
# Print a list of testcases that failed
if ( $tot_failed != 0 )
{
# Print each failed test, again
#foreach my $test ( @$tests ){
# if ( $test->{failures} ) {
# mtr_report_test($test);
# }
#}
my $ratio= $tot_passed * 100 / $tot_tests;
print "Failed $tot_failed/$tot_tests tests, ";
printf("%.2f", $ratio);
print "\% were successful.\n\n";
# Print the list of test that failed in a format
# that can be copy pasted to rerun only failing tests
print "Failing test(s):";
my %seen= ();
foreach my $tinfo (@$tests)
{
my $tname= $tinfo->{'name'};
if ( ($tinfo->{failures} || $tinfo->{rep_failures}) and ! $seen{$tname})
{
print " $tname";
$seen{$tname}= 1;
}
}
print "\n\n";
# Print info about reporting the error
print
"The log files in var/log may give you some hint of what went wrong.\n\n",
"If you want to report this error, please read first ",
"the documentation\n",
"at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html\n\n";
}
else
{
print "All $tot_tests tests were successful.\n\n";
}
if ($::opt_xml_report) {
my $xml_report = "";
my @sorted_tests = sort {$a->{'name'} cmp $b->{'name'}} @$tests;
my $last_suite = "";
my $current_suite = "";
my $timest = isotime(time);
my %suite_totals;
my %suite_time;
my %suite_tests;
my %suite_failed;
my %suite_disabled;
my %suite_skipped;
my $host = hostname;
my $suiteNo = 0;
# loop through test results to count totals
foreach my $test ( @sorted_tests ) {
$current_suite = $test->{'suite'}->{'name'};
if ($test->{'timer'} eq "") {
$test->{'timer'} = 0;
}
$suite_time{$current_suite} = $suite_time{$current_suite} + $test->{'timer'};
$suite_tests{$current_suite} = $suite_tests{$current_suite} + 1;
if ($test->{'result'} eq "MTR_RES_FAILED") {
$suite_failed{$current_suite} = $suite_failed{$current_suite} + 1;
} elsif ($test->{'result'} eq "MTR_RES_SKIPPED" && $test->{'disable'}) {
$suite_disabled{$current_suite} = $suite_disabled{$current_suite} + 1;
} elsif ($test->{'result'} eq "MTR_RES_SKIPPED") {
$suite_skipped{$current_suite} = $suite_skipped{$current_suite} + 1;
}
$suite_totals{"all_time"} = $suite_totals{"all_time"} + $test->{'timer'};
}
my $all_time = sprintf("%.3f", $suite_totals{"all_time"} / 1000);
my $suite_time = 0;
my $test_time = 0;
# generate xml
$xml_report = "<?xml version=\"1.0\" encoding=\"UTF-8\"?>\n";
$xml_report .= qq(<testsuites disabled="$tot_disabled" errors="" failures="$tot_failed" name="" tests="$tot_tests" time="$all_time">\n);
foreach my $test ( @sorted_tests ) {
$current_suite = $test->{'suite'}->{'name'};
if ($current_suite ne $last_suite) {
if ($last_suite ne "") {
$xml_report .= "\t</testsuite>\n";
$suiteNo++;
}
$suite_time = sprintf("%.3f", $suite_time{$current_suite} / 1000);
$xml_report .= qq(\t<testsuite disabled="$suite_disabled{$current_suite}" errors="" failures="$suite_failed{$current_suite}" hostname="$host" id="$suiteNo" name="$current_suite" package="" skipped="$suite_skipped{$current_suite}" tests="$suite_tests{$current_suite}" time="$suite_time" timestamp="$timest">\n);
$last_suite = $current_suite;
}
$test_time = sprintf("%.3f", $test->{timer} / 1000);
$test->{'name'} =~ s/$current_suite\.//;
my $combinations;
if (defined($test->{combinations})){
$combinations = join ',', sort @{$test->{combinations}};
} else {
$combinations = "";
}
$xml_report .= qq(\t\t<testcase assertions="" classname="$current_suite" name="$test->{'name'}" ).
qq(status="$test->{'result'}" time="$test_time" combinations="$combinations");
my $comment= replace_special_symbols($test->{'comment'});
if ($test->{'result'} eq "MTR_RES_FAILED") {
my $logcontents = $test->{'logfile-failed'} || $test->{'logfile'};
$logcontents= $logcontents.$test->{'warnings'}."\n";
# remove any double ] that would end the cdata
$logcontents =~ s/]]/\x{fffd}/g;
# replace wide characters that aren't allowed in XML 1.0
$logcontents =~ s/[\x00-\x08\x0B\x0C\x0E-\x1F]/\x{fffd}/g;
$xml_report .= qq(>\n\t\t\t<failure message="" type="MTR_RES_FAILED">\n<![CDATA[$logcontents]]>\n\t\t\t</failure>\n\t\t</testcase>\n);
} elsif ($test->{'result'} eq "MTR_RES_SKIPPED" && $test->{'disable'}) {
$xml_report .= qq(>\n\t\t\t<disabled message="$comment" type="MTR_RES_SKIPPED"/>\n\t\t</testcase>\n);
} elsif ($test->{'result'} eq "MTR_RES_SKIPPED") {
$xml_report .= qq(>\n\t\t\t<skipped message="$comment" type="MTR_RES_SKIPPED"/>\n\t\t</testcase>\n);
} else {
$xml_report .= " />\n";
}
}
$xml_report .= "\t</testsuite>\n</testsuites>\n";
# save to file
my $xml_file = $::opt_xml_report;
open (my $XML_UFILE, '>:encoding(UTF-8)', $xml_file) or die 'Cannot create file $xml_file: $!';
print $XML_UFILE $xml_report;
close $XML_UFILE or warn "File close failed!";
}
if (@$extra_warnings)
{
print <<MSG;
Errors/warnings were found in logfiles during server shutdown after running the
following sequence(s) of tests:
MSG
print " $_\n" for @$extra_warnings;
}
print "$tot_skipped tests were skipped, ".
"$tot_skipdetect by the test itself.\n\n" if $tot_skipped;
if ( $tot_failed != 0 || $found_problems)
{
mtr_error("there were failing test cases");
}
elsif (@$extra_warnings)
{
mtr_error("There where errors/warnings in server logs after running test cases.");
}
elsif ($fail)
{
mtr_error("Test suite failure, see messages above for possible cause(s).");
}
}
##############################################################################
#
# Text formatting
#
##############################################################################
sub mtr_print_line () {
print '-' x 74 . "\n";
}
sub replace_special_symbols($) {
my $text= shift;
$text =~ s/&/&#38;/g;
$text =~ s/'/&#39;/g;
$text =~ s/"/&#34;/g;
$text =~ s/</&lt;/g;
$text =~ s/>/&gt;/g;
return $text;
}
sub mtr_print_thick_line {
my $char= shift || '=';
print $char x 78 . "\n";
}
sub mtr_print_header ($) {
my ($wid) = @_;
print "\n";
printf "TEST";
if ($wid) {
print " " x 34 . "WORKER ";
} else {
print " " x 38;
}
print "RESULT ";
print "TIME (ms) or " if $timer;
print "COMMENT\n";
mtr_print_line();
print "\n";
}
##############################################################################
#
# Log and reporting functions
#
##############################################################################
use Time::localtime;
use Time::HiRes qw(gettimeofday);
sub format_time {
my $tm= localtime();
return sprintf("%4d-%02d-%02d %02d:%02d:%02d",
$tm->year + 1900, $tm->mon+1, $tm->mday,
$tm->hour, $tm->min, $tm->sec);
}
my $t0= gettimeofday();
sub _timestamp {
return "" unless $timestamp;
my $diff;
if ($timediff){
my $t1= gettimeofday();
my $elapsed= $t1 - $t0;
$diff= sprintf(" +%02.3f", $elapsed);
# Save current time for next lap
$t0= $t1;
}
my $tm= localtime();
return sprintf("%02d%02d%02d %2d:%02d:%02d%s ",
$tm->year % 100, $tm->mon+1, $tm->mday,
$tm->hour, $tm->min, $tm->sec, $diff);
}
# Always print message to screen
sub mtr_print (@) {
print _name(). join(" ", @_). "\n";
}
# Print message to screen if verbose is defined
sub mtr_report (@) {
if (defined $verbose)
{
my @s = split /\[ (\S+) \]/, _name() . "@_\n";
if (@s > 1) {
print_out $s[0];
&$set_color($s[1]);
print_out "[ $s[1] ]";
&$set_color('reset');
print_out $s[2];
titlebar_stat($s[1]) if $set_titlebar;
} else {
print_out $s[0];
}
}
}
# Print warning to screen
sub mtr_warning (@) {
flush_out();
print STDERR _name(). _timestamp().
"mysql-test-run: WARNING: ". join(" ", @_). "\n";
}
# Print error to screen and then exit
sub mtr_error (@) {
flush_out();
print STDERR _name(). _timestamp().
"mysql-test-run: *** ERROR: ". join(" ", @_). "\n";
if (IS_WINDOWS)
{
POSIX::_exit(1);
}
else
{
use Carp qw(cluck);
cluck "Error happened" if $verbose > 0;
exit(1);
}
}
sub mtr_debug (@) {
if ( $verbose > 2 )
{
print STDERR _name().
_timestamp(). "####: ". join(" ", @_). "\n";
}
}
sub mtr_verbose (@) {
if ( $verbose )
{
print STDERR _name(). _timestamp().
"> ".join(" ", @_)."\n";
}
}
sub mtr_verbose2 (@) {
if ( $verbose > 1 )
{
print STDERR _name(). _timestamp().
"> ".join(" ", @_)."\n";
}
}
sub mtr_verbose_restart (@) {
my ($server, @args)= @_;
my $proc= $server->{proc};
if ( $verbose_restart )
{
print STDERR _name()._timestamp().
"> Restart $proc - ".join(" ", @args)."\n";
}
}
# Used by --result-file for for formatting times
sub isotime($) {
my ($sec,$min,$hr,$day,$mon,$yr)= gmtime($_[0]);
return sprintf "%d-%02d-%02dT%02d:%02d:%02dZ",
$yr+1900, $mon+1, $day, $hr, $min, $sec;
}
1;