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