1# -*- cperl -*- 2# Copyright (c) 2004, 2011, Oracle and/or its affiliates. All rights reserved. 3# 4# This program is free software; you can redistribute it and/or modify 5# it under the terms of the GNU General Public License as published by 6# the Free Software Foundation; version 2 of the License. 7# 8# This program is distributed in the hope that it will be useful, 9# but WITHOUT ANY WARRANTY; without even the implied warranty of 10# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 11# GNU General Public License for more details. 12# 13# You should have received a copy of the GNU General Public License 14# along with this program; if not, write to the Free Software 15# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA 16 17# This is a library file used by the Perl version of mysql-test-run, 18# and is part of the translation of the Bourne shell script with the 19# same name. 20 21package mtr_report; 22use strict; 23 24use base qw(Exporter); 25our @EXPORT= qw(report_option mtr_print_line mtr_print_thick_line 26 mtr_print_header mtr_report mtr_report_stats 27 mtr_warning mtr_error mtr_debug mtr_verbose 28 mtr_verbose_restart mtr_report_test_passed 29 mtr_report_test_skipped mtr_print 30 mtr_report_test isotime); 31 32use mtr_match; 33use My::Platform; 34use POSIX qw[ _exit ]; 35use IO::Handle qw[ flush ]; 36require "mtr_io.pl"; 37use mtr_results; 38 39my $tot_real_time= 0; 40 41our $timestamp= 0; 42our $timediff= 0; 43our $name; 44our $verbose; 45our $verbose_restart= 0; 46our $timer= 1; 47 48sub report_option { 49 my ($opt, $value)= @_; 50 51 # Evaluate $opt as string to use "Getopt::Long::Callback legacy API" 52 my $opt_name = "$opt"; 53 54 # Convert - to _ in option name 55 $opt_name =~ s/-/_/g; 56 no strict 'refs'; 57 ${$opt_name}= $value; 58} 59 60sub _name { 61 return $name ? $name." " : undef; 62} 63 64sub _mtr_report_test_name ($) { 65 my $tinfo= shift; 66 my $tname= $tinfo->{name}; 67 68 return unless defined $verbose; 69 70 # Add combination name if any 71 $tname.= " '$tinfo->{combination}'" 72 if defined $tinfo->{combination}; 73 74 print _name(). _timestamp(); 75 printf "%-40s ", $tname; 76 my $worker = $tinfo->{worker}; 77 print "w$worker " if defined $worker; 78 79 return $tname; 80} 81 82 83sub mtr_report_test_skipped ($) { 84 my ($tinfo)= @_; 85 $tinfo->{'result'}= 'MTR_RES_SKIPPED'; 86 87 mtr_report_test($tinfo); 88} 89 90 91sub mtr_report_test_passed ($) { 92 my ($tinfo)= @_; 93 94 # Save the timer value 95 my $timer_str= ""; 96 if ( $timer and -f "$::opt_vardir/log/timer" ) 97 { 98 $timer_str= mtr_fromfile("$::opt_vardir/log/timer"); 99 $tinfo->{timer}= $timer_str; 100 resfile_test_info('duration', $timer_str) if $::opt_resfile; 101 } 102 103 # Big warning if status already set 104 if ( $tinfo->{'result'} ){ 105 mtr_warning("mtr_report_test_passed: Test result", 106 "already set to '", $tinfo->{'result'}, ","); 107 } 108 109 $tinfo->{'result'}= 'MTR_RES_PASSED'; 110 111 mtr_report_test($tinfo); 112 113 resfile_global("endtime ", isotime (time)); 114} 115 116 117sub mtr_report_test ($) { 118 my ($tinfo)= @_; 119 my $test_name = _mtr_report_test_name($tinfo); 120 121 my $comment= $tinfo->{'comment'}; 122 my $logfile= $tinfo->{'logfile'}; 123 my $warnings= $tinfo->{'warnings'}; 124 my $result= $tinfo->{'result'}; 125 my $retry= $tinfo->{'retries'} ? "retry-" : ""; 126 127 if ($result eq 'MTR_RES_FAILED'){ 128 129 my $timest = format_time(); 130 my $fail = "fail"; 131 132 if ( @$::experimental_test_cases ) 133 { 134 # Find out if this test case is an experimental one, so we can treat 135 # the failure as an expected failure instead of a regression. 136 for my $exp ( @$::experimental_test_cases ) { 137 # Include pattern match for combinations 138 if ( $exp ne $test_name && $test_name !~ /^$exp / ) { 139 # if the expression is not the name of this test case, but has 140 # an asterisk at the end, determine if the characters up to 141 # but excluding the asterisk are the same 142 if ( $exp ne "" && substr($exp, -1, 1) eq "*" ) { 143 my $nexp = substr($exp, 0, length($exp) - 1); 144 if ( substr($test_name, 0, length($nexp)) ne $nexp ) { 145 # no match, try next entry 146 next; 147 } 148 # if yes, fall through to set the exp-fail status 149 } else { 150 # no match, try next entry 151 next; 152 } 153 } 154 $fail = "exp-fail"; 155 $tinfo->{exp_fail}= 1; 156 last; 157 } 158 } 159 160 if ( $warnings ) 161 { 162 mtr_report("[ $retry$fail ] Found warnings/errors in server log file!"); 163 mtr_report(" Test ended at $timest"); 164 mtr_report($warnings); 165 return; 166 } 167 my $timeout= $tinfo->{'timeout'}; 168 if ( $timeout ) 169 { 170 mtr_report("[ $retry$fail ] timeout after $timeout seconds"); 171 mtr_report(" Test ended at $timest"); 172 mtr_report("\n$tinfo->{'comment'}"); 173 return; 174 } 175 else 176 { 177 mtr_report("[ $retry$fail ]\n Test ended at $timest"); 178 } 179 180 if ( $logfile ) 181 { 182 # Test failure was detected by test tool and its report 183 # about what failed has been saved to file. Display the report. 184 mtr_report("\n$logfile\n"); 185 } 186 if ( $comment ) 187 { 188 # The test failure has been detected by mysql-test-run.pl 189 # when starting the servers or due to other error, the reason for 190 # failing the test is saved in "comment" 191 mtr_report("\n$comment\n"); 192 } 193 194 if ( !$logfile and !$comment ) 195 { 196 # Neither this script or the test tool has recorded info 197 # about why the test has failed. Should be debugged. 198 mtr_report("\nUnknown result, neither 'comment' or 'logfile' set"); 199 } 200 } 201 elsif ($result eq 'MTR_RES_SKIPPED') 202 { 203 if ( $tinfo->{'disable'} ) 204 { 205 mtr_report("[ disabled ] $comment"); 206 } 207 elsif ( $comment ) 208 { 209 mtr_report("[ skipped ] $comment"); 210 } 211 else 212 { 213 mtr_report("[ skipped ]"); 214 } 215 } 216 elsif ($result eq 'MTR_RES_PASSED') 217 { 218 my $timer_str= $tinfo->{timer} || ""; 219 $tot_real_time += ($timer_str/1000); 220 mtr_report("[ ${retry}pass ] ", sprintf("%5s", $timer_str)); 221 222 # Show any problems check-testcase found 223 if ( defined $tinfo->{'check'} ) 224 { 225 mtr_report($tinfo->{'check'}); 226 } 227 } 228} 229 230 231sub mtr_report_stats ($$;$) { 232 my ($prefix, $tests, $dont_error)= @_; 233 234 # ---------------------------------------------------------------------- 235 # Find out how we where doing 236 # ---------------------------------------------------------------------- 237 238 my $tot_skipped= 0; 239 my $tot_skipdetect= 0; 240 my $tot_passed= 0; 241 my $tot_failed= 0; 242 my $tot_tests= 0; 243 my $tot_restarts= 0; 244 my $found_problems= 0; 245 246 foreach my $tinfo (@$tests) 247 { 248 if ( $tinfo->{failures} ) 249 { 250 # Test has failed at least one time 251 $tot_tests++; 252 $tot_failed++; 253 } 254 elsif ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' ) 255 { 256 # Test was skipped (disabled not counted) 257 $tot_skipped++ unless $tinfo->{'disable'}; 258 $tot_skipdetect++ if $tinfo->{'skip_detected_by_test'}; 259 } 260 elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' ) 261 { 262 # Test passed 263 $tot_tests++; 264 $tot_passed++; 265 } 266 267 if ( $tinfo->{'restarted'} ) 268 { 269 # Servers was restarted 270 $tot_restarts++; 271 } 272 273 # Add counts for repeated runs, if any. 274 # Note that the last run has already been counted above. 275 my $num_repeat = $tinfo->{'repeat'} - 1; 276 if ( $num_repeat > 0 ) 277 { 278 $tot_tests += $num_repeat; 279 my $rep_failed = $tinfo->{'rep_failures'} || 0; 280 $tot_failed += $rep_failed; 281 $tot_passed += $num_repeat - $rep_failed; 282 } 283 284 # Look for warnings produced by mysqltest 285 my $base_file= mtr_match_extension($tinfo->{'result_file'}, 286 "result"); # Trim extension 287 my $warning_file= "$base_file.warnings"; 288 if ( -f $warning_file ) 289 { 290 $found_problems= 1; 291 mtr_warning("Check myqltest warnings in '$warning_file'"); 292 } 293 } 294 295 # ---------------------------------------------------------------------- 296 # Print out a summary report to screen 297 # ---------------------------------------------------------------------- 298 print "The servers were restarted $tot_restarts times\n"; 299 300 if ( $timer ) 301 { 302 use English; 303 304 mtr_report("Spent", sprintf("%.3f", $tot_real_time),"of", 305 time - $BASETIME, "seconds executing testcases"); 306 } 307 308 resfile_global("duration", time - $BASETIME) if $::opt_resfile; 309 310 my $warnlog= "$::opt_vardir/log/warnings"; 311 if ( -f $warnlog ) 312 { 313 mtr_warning("Got errors/warnings while running tests, please examine", 314 "'$warnlog' for details."); 315 } 316 317 print "\n"; 318 319 # Print a list of check_testcases that failed(if any) 320 if ( $::opt_check_testcases ) 321 { 322 my %check_testcases; 323 324 foreach my $tinfo (@$tests) 325 { 326 if ( defined $tinfo->{'check_testcase_failed'} ) 327 { 328 $check_testcases{$tinfo->{'name'}}= 1; 329 } 330 } 331 332 if ( keys %check_testcases ) 333 { 334 print "Check of testcase failed for: "; 335 print join(" ", keys %check_testcases); 336 print "\n\n"; 337 } 338 } 339 340 # Print summary line prefix 341 print "$prefix: "; 342 343 # Print a list of testcases that failed 344 if ( $tot_failed != 0 ) 345 { 346 347 # Print each failed test, again 348 #foreach my $test ( @$tests ){ 349 # if ( $test->{failures} ) { 350 # mtr_report_test($test); 351 # } 352 #} 353 354 my $ratio= $tot_passed * 100 / $tot_tests; 355 print "Failed $tot_failed/$tot_tests tests, "; 356 printf("%.2f", $ratio); 357 print "\% were successful.\n\n"; 358 359 # Print the list of test that failed in a format 360 # that can be copy pasted to rerun only failing tests 361 print "Failing test(s):"; 362 363 my %seen= (); 364 foreach my $tinfo (@$tests) 365 { 366 my $tname= $tinfo->{'name'}; 367 if ( ($tinfo->{failures} || $tinfo->{rep_failures}) and ! $seen{$tname}) 368 { 369 print " $tname"; 370 $seen{$tname}= 1; 371 } 372 } 373 print "\n\n"; 374 375 # Print info about reporting the error 376 print 377 "The log files in var/log may give you some hint of what went wrong.\n\n", 378 "If you want to report this error, please read first ", 379 "the documentation\n", 380 "at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html\n\n"; 381 382 } 383 else 384 { 385 print "All $tot_tests tests were successful.\n\n"; 386 } 387 388 print "$tot_skipped tests were skipped, ". 389 "$tot_skipdetect by the test itself.\n\n" if $tot_skipped; 390 391 if ( $tot_failed != 0 || $found_problems) 392 { 393 mtr_error("there were failing test cases") unless $dont_error; 394 } 395} 396 397 398############################################################################## 399# 400# Text formatting 401# 402############################################################################## 403 404sub mtr_print_line () { 405 print '-' x 74 . "\n"; 406} 407 408 409sub mtr_print_thick_line { 410 my $char= shift || '='; 411 print $char x 78 . "\n"; 412} 413 414 415sub mtr_print_header ($) { 416 my ($wid) = @_; 417 print "\n"; 418 printf "TEST"; 419 if ($wid) { 420 print " " x 34 . "WORKER "; 421 } else { 422 print " " x 38; 423 } 424 print "RESULT "; 425 print "TIME (ms) or " if $timer; 426 print "COMMENT\n"; 427 mtr_print_line(); 428 print "\n"; 429} 430 431 432############################################################################## 433# 434# Log and reporting functions 435# 436############################################################################## 437 438use Time::localtime; 439 440use Time::HiRes qw(gettimeofday); 441 442sub format_time { 443 my $tm= localtime(); 444 return sprintf("%4d-%02d-%02d %02d:%02d:%02d", 445 $tm->year + 1900, $tm->mon+1, $tm->mday, 446 $tm->hour, $tm->min, $tm->sec); 447} 448 449my $t0= gettimeofday(); 450 451sub _timestamp { 452 return "" unless $timestamp; 453 454 my $diff; 455 if ($timediff){ 456 my $t1= gettimeofday(); 457 my $elapsed= $t1 - $t0; 458 459 $diff= sprintf(" +%02.3f", $elapsed); 460 461 # Save current time for next lap 462 $t0= $t1; 463 464 } 465 466 my $tm= localtime(); 467 return sprintf("%02d%02d%02d %2d:%02d:%02d%s ", 468 $tm->year % 100, $tm->mon+1, $tm->mday, 469 $tm->hour, $tm->min, $tm->sec, $diff); 470} 471 472# Always print message to screen 473sub mtr_print (@) { 474 print _name(). join(" ", @_). "\n"; 475} 476 477 478# Print message to screen if verbose is defined 479sub mtr_report (@) { 480 if (defined $verbose) 481 { 482 print _name(). join(" ", @_). "\n"; 483 } 484} 485 486 487# Print warning to screen 488sub mtr_warning (@) { 489 print STDERR _name(). _timestamp(). 490 "mysql-test-run: WARNING: ". join(" ", @_). "\n"; 491} 492 493 494# Print error to screen and then exit 495sub mtr_error (@) { 496 IO::Handle::flush(\*STDOUT) if IS_WINDOWS; 497 print STDERR _name(). _timestamp(). 498 "mysql-test-run: *** ERROR: ". join(" ", @_). "\n"; 499 if (IS_WINDOWS) 500 { 501 POSIX::_exit(1); 502 } 503 else 504 { 505 exit(1); 506 } 507} 508 509 510sub mtr_debug (@) { 511 if ( $verbose > 2 ) 512 { 513 print STDERR _name(). 514 _timestamp(). "####: ". join(" ", @_). "\n"; 515 } 516} 517 518 519sub mtr_verbose (@) { 520 if ( $verbose ) 521 { 522 print STDERR _name(). _timestamp(). 523 "> ".join(" ", @_)."\n"; 524 } 525} 526 527 528sub mtr_verbose_restart (@) { 529 my ($server, @args)= @_; 530 my $proc= $server->{proc}; 531 if ( $verbose_restart ) 532 { 533 print STDERR _name()._timestamp(). 534 "> Restart $proc - ".join(" ", @args)."\n"; 535 } 536} 537 538 539# Used by --result-file for for formatting times 540 541sub isotime($) { 542 my ($sec,$min,$hr,$day,$mon,$yr)= gmtime($_[0]); 543 return sprintf "%d-%02d-%02dT%02d:%02d:%02dZ", 544 $yr+1900, $mon+1, $day, $hr, $min, $sec; 545} 546 5471; 548