diff options
Diffstat (limited to 'mysql-test/lib/mtr_report.pm')
| -rw-r--r-- | mysql-test/lib/mtr_report.pm | 773 |
1 files changed, 773 insertions, 0 deletions
diff --git a/mysql-test/lib/mtr_report.pm b/mysql-test/lib/mtr_report.pm new file mode 100644 index 00000000..97c48c19 --- /dev/null +++ b/mysql-test/lib/mtr_report.pm @@ -0,0 +1,773 @@ +# -*- 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/&/&/g; + $text =~ s/'/'/g; + $text =~ s/"/"/g; + $text =~ s/</</g; + $text =~ s/>/>/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; |