mtr_report.pl 14.3 KB
Newer Older
kent@mysql.com's avatar
kent@mysql.com committed
1
# -*- cperl -*-
2 3 4 5 6 7 8 9 10 11 12 13 14 15
# Copyright (C) 2004-2006 MySQL 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-1301  USA
kent@mysql.com's avatar
kent@mysql.com committed
16 17 18 19 20 21 22 23 24 25 26

# 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.

use strict;

sub mtr_report_test_name($);
sub mtr_report_test_passed($);
sub mtr_report_test_failed($);
sub mtr_report_test_skipped($);
27
sub mtr_report_test_not_skipped_though_disabled($);
kent@mysql.com's avatar
kent@mysql.com committed
28 29 30 31

sub mtr_show_failed_diff ($);
sub mtr_report_stats ($);
sub mtr_print_line ();
kent@mysql.com's avatar
kent@mysql.com committed
32
sub mtr_print_thick_line ();
kent@mysql.com's avatar
kent@mysql.com committed
33 34 35 36
sub mtr_print_header ();
sub mtr_report (@);
sub mtr_warning (@);
sub mtr_error (@);
37
sub mtr_child_error (@);
kent@mysql.com's avatar
kent@mysql.com committed
38
sub mtr_debug (@);
39
sub mtr_verbose (@);
kent@mysql.com's avatar
kent@mysql.com committed
40 41 42 43 44 45 46 47 48 49 50


##############################################################################
#
#  
#
##############################################################################

# We can't use diff -u or diff -a as these are not portable

sub mtr_show_failed_diff ($) {
51 52 53 54 55 56
  my $result_file_name=  shift;

  # The reject and log files have been dumped to
  # to filenames based on the result_file's name
  my $tname= basename($result_file_name);
  $tname=~ s/\..*$//;
kent@mysql.com's avatar
kent@mysql.com committed
57 58 59

  my $reject_file=  "r/$tname.reject";
  my $result_file=  "r/$tname.result";
60
  my $log_file=     "$::opt_vardir/log/$tname.log";
kent@mysql.com's avatar
kent@mysql.com committed
61 62
  my $eval_file=    "r/$tname.eval";

kent@mysql.com's avatar
kent@mysql.com committed
63 64 65 66 67
  if ( $::opt_suite ne "main" )
  {
    $reject_file= "$::glob_mysql_test_dir/suite/$::opt_suite/$reject_file";
    $result_file= "$::glob_mysql_test_dir/suite/$::opt_suite/$result_file";
    $eval_file=   "$::glob_mysql_test_dir/suite/$::opt_suite/$eval_file";
68
    $log_file=   "$::glob_mysql_test_dir/suite/$::opt_suite/$log_file";
kent@mysql.com's avatar
kent@mysql.com committed
69 70
  }

kent@mysql.com's avatar
kent@mysql.com committed
71
  if ( -f $eval_file )
72
  {
kent@mysql.com's avatar
kent@mysql.com committed
73 74 75
    $result_file=  $eval_file;
  }

kent@mysql.com's avatar
kent@mysql.com committed
76 77
  my $diffopts= $::opt_udiff ? "-u" : "-c";

kent@mysql.com's avatar
kent@mysql.com committed
78 79 80 81 82
  if ( -f $reject_file )
  {
    print "Below are the diffs between actual and expected results:\n";
    print "-------------------------------------------------------\n";
    # FIXME check result code?!
kent@mysql.com's avatar
kent@mysql.com committed
83
    mtr_run("diff",[$diffopts,$result_file,$reject_file], "", "", "", "");
kent@mysql.com's avatar
kent@mysql.com committed
84 85 86 87 88
    print "-------------------------------------------------------\n";
    print "Please follow the instructions outlined at\n";
    print "http://www.mysql.com/doc/en/Reporting_mysqltest_bugs.html\n";
    print "to find the reason to this problem and how to report this.\n\n";
  }
89 90 91 92 93 94

  if ( -f $log_file )
  {
    print "Result from queries before failure can be found in $log_file\n";
    # FIXME Maybe a tail -f -n 10 $log_file here
  }
kent@mysql.com's avatar
kent@mysql.com committed
95 96 97 98 99
}

sub mtr_report_test_name ($) {
  my $tinfo= shift;

100
  printf "%-30s ", $tinfo->{'name'};
kent@mysql.com's avatar
kent@mysql.com committed
101 102 103 104 105 106
}

sub mtr_report_test_skipped ($) {
  my $tinfo= shift;

  $tinfo->{'result'}= 'MTR_RES_SKIPPED';
kent@mysql.com's avatar
kent@mysql.com committed
107 108 109 110
  if ( $tinfo->{'disable'} )
  {
    print "[ disabled ]  $tinfo->{'comment'}\n";
  }
111
  elsif ( $tinfo->{'comment'} )
kent@mysql.com's avatar
kent@mysql.com committed
112
  {
113 114
    print "[ skipped ]   $tinfo->{'comment'}\n";
  }
115 116 117 118
  else
  {
    print "[ skipped ]\n";
  }
119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134
}

sub mtr_report_tests_not_skipped_though_disabled ($) {
  my $tests= shift;

  if ( $::opt_enable_disabled )
  {
    my @disabled_tests= grep {$_->{'dont_skip_though_disabled'}} @$tests;
    if ( @disabled_tests )
    {
      print "\nTest(s) which will be run though they are marked as disabled:\n";
      foreach my $tinfo ( sort {$a->{'name'} cmp $b->{'name'}} @disabled_tests )
      {
        printf "  %-20s : %s\n", $tinfo->{'name'}, $tinfo->{'comment'};
      }
    }
kent@mysql.com's avatar
kent@mysql.com committed
135
  }
kent@mysql.com's avatar
kent@mysql.com committed
136 137 138 139 140 141
}

sub mtr_report_test_passed ($) {
  my $tinfo= shift;

  my $timer=  "";
142
  if ( $::opt_timer and -f "$::opt_vardir/log/timer" )
kent@mysql.com's avatar
kent@mysql.com committed
143
  {
144
    $timer= mtr_fromfile("$::opt_vardir/log/timer");
145
    $::glob_tot_real_time += ($timer/1000);
kent@mysql.com's avatar
kent@mysql.com committed
146 147
    $timer= sprintf "%12s", $timer;
  }
kent@mysql.com's avatar
kent@mysql.com committed
148 149 150 151 152 153 154 155
  $tinfo->{'result'}= 'MTR_RES_PASSED';
  print "[ pass ]   $timer\n";
}

sub mtr_report_test_failed ($) {
  my $tinfo= shift;

  $tinfo->{'result'}= 'MTR_RES_FAILED';
msvensson@shellback.(none)'s avatar
msvensson@shellback.(none) committed
156
  if ( defined $tinfo->{'timeout'} )
157 158
  {
    print "[ fail ]  timeout\n";
159
    return;
160 161 162 163 164
  }
  else
  {
    print "[ fail ]\n";
  }
kent@mysql.com's avatar
kent@mysql.com committed
165

166 167 168 169 170
  if ( $tinfo->{'comment'} )
  {
    print "\nERROR: $tinfo->{'comment'}\n";
  }
  elsif ( -f $::path_timefile )
kent@mysql.com's avatar
kent@mysql.com committed
171
  {
172
    print "\nErrors are (from $::path_timefile) :\n";
kent@mysql.com's avatar
kent@mysql.com committed
173 174 175 176 177
    print mtr_fromfile($::path_timefile); # FIXME print_file() instead
    print "\n(the last lines may be the most important ones)\n";
  }
  else
  {
178
    print "\nUnexpected termination, probably when starting mysqld\n";
kent@mysql.com's avatar
kent@mysql.com committed
179
  }
kent@mysql.com's avatar
kent@mysql.com committed
180 181 182 183 184 185 186 187 188 189 190 191 192
}

sub mtr_report_stats ($) {
  my $tests= shift;

  # ----------------------------------------------------------------------
  # Find out how we where doing
  # ----------------------------------------------------------------------

  my $tot_skiped= 0;
  my $tot_passed= 0;
  my $tot_failed= 0;
  my $tot_tests=  0;
193
  my $tot_restarts= 0;
194
  my $found_problems= 0; # Some warnings in the logfiles are errors...
kent@mysql.com's avatar
kent@mysql.com committed
195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211

  foreach my $tinfo (@$tests)
  {
    if ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' )
    {
      $tot_skiped++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' )
    {
      $tot_tests++;
      $tot_passed++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_FAILED' )
    {
      $tot_tests++;
      $tot_failed++;
    }
212 213 214 215
    if ( $tinfo->{'restarted'} )
    {
      $tot_restarts++;
    }
kent@mysql.com's avatar
kent@mysql.com committed
216 217 218 219 220 221 222 223 224 225 226 227 228
  }

  # ----------------------------------------------------------------------
  # Print out a summary report to screen
  # ----------------------------------------------------------------------

  if ( ! $tot_failed )
  {
    print "All $tot_tests tests were successful.\n";
  }
  else
  {
    my $ratio=  $tot_passed * 100 / $tot_tests;
229 230 231
    print "Failed $tot_failed/$tot_tests tests, ";
    printf("%.2f", $ratio);
    print "\% were successful.\n\n";
kent@mysql.com's avatar
kent@mysql.com committed
232 233
    print
      "The log files in var/log may give you some hint\n",
234
      "of what went wrong.\n",
kent@mysql.com's avatar
kent@mysql.com committed
235 236 237 238
      "If you want to report this error, please read first ",
      "the documentation at\n",
      "http://www.mysql.com/doc/en/MySQL_test_suite.html\n";
  }
239 240
  if (!$::opt_extern)
  {
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
241
    print "The servers were restarted $tot_restarts times\n";
242
  }
243 244 245 246 247 248

  if ( $::opt_timer )
  {
    print
      "Spent $::glob_tot_real_time seconds actually executing testcases\n"
  }
kent@mysql.com's avatar
kent@mysql.com committed
249 250

  # ----------------------------------------------------------------------
251 252
  # If a debug run, there might be interesting information inside
  # the "var/log/*.err" files. We save this info in "var/log/warnings"
kent@mysql.com's avatar
kent@mysql.com committed
253 254 255 256
  # ----------------------------------------------------------------------

  if ( ! $::glob_use_running_server )
  {
257
    # Save and report if there was any fatal warnings/errors in err logs
kent@mysql.com's avatar
kent@mysql.com committed
258

259 260 261 262 263 264 265 266 267
    my $warnlog= "$::opt_vardir/log/warnings";

    unless ( open(WARN, ">$warnlog") )
    {
      mtr_warning("can't write to the file \"$warnlog\": $!");
    }
    else
    {
      # We report different types of problems in order
268 269 270 271 272 273 274
      foreach my $pattern ( "^Warning:",
			    "\\[Warning\\]",
			    "\\[ERROR\\]",
			    "^Error:", "^==.* at 0x",
			    "InnoDB: Warning",
			    "^safe_mutex:",
			    "missing DBUG_RETURN",
275
			    "mysqld: Warning",
276
			    "allocated at line",
277 278 279 280
			    "Attempting backtrace", "Assertion .* failed" )
      {
        foreach my $errlog ( sort glob("$::opt_vardir/log/*.err") )
        {
281
	  my $testname= "";
282 283 284 285 286
          unless ( open(ERR, $errlog) )
          {
            mtr_warning("can't read $errlog");
            next;
          }
287
          my $leak_reports_expected= undef;
288 289
          while ( <ERR> )
          {
290 291 292 293 294 295 296 297 298 299
            # There is a test case that purposely provokes a
            # SAFEMALLOC leak report, even though there is no actual
            # leak. We need to detect this, and ignore the warning in
            # that case.
            if (/Begin safemalloc memory dump:/) {
              $leak_reports_expected= 1;
            } elsif (/End safemalloc memory dump./) {
              $leak_reports_expected= undef;
            }

300
            # Skip some non fatal warnings from the log files
301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361
            if (
		/\"SELECT UNIX_TIMESTAMP\(\)\" failed on master/ or
		/Aborted connection/ or
		/Client requested master to start replication from impossible position/ or
		/Could not find first log file name in binary log/ or
		/Enabling keys got errno/ or
		/Error reading master configuration/ or
		/Error reading packet/ or
		/Event Scheduler/ or
		/Failed to open log/ or
		/Failed to open the existing master info file/ or
		/Forcing shutdown of [0-9]* plugins/ or
		/Got error [0-9]* when reading table/ or
		/Incorrect definition of table/ or
		/Incorrect information in file/ or
		/InnoDB: Warning: we did not need to do crash recovery/ or
		/Invalid \(old\?\) table or database name/ or
		/Lock wait timeout exceeded/ or
		/Log entry on master is longer than max_allowed_packet/ or
                /unknown option '--loose-/ or
                /unknown variable 'loose-/ or
		/You have forced lower_case_table_names to 0 through a command-line option/ or
		/Setting lower_case_table_names=2/ or
		/NDB Binlog:/ or
		/NDB: failed to setup table/ or
		/NDB: only row based binary logging/ or
		/Neither --relay-log nor --relay-log-index were used/ or
		/Query partially completed/ or
		/Slave I.O thread aborted while waiting for relay log/ or
		/Slave SQL thread is stopped because UNTIL condition/ or
		/Slave SQL thread retried transaction/ or
		/Slave \(additional info\)/ or
		/Slave: .*Duplicate column name/ or
		/Slave: .*master may suffer from/ or
		/Slave: According to the master's version/ or
		/Slave: Column [0-9]* type mismatch/ or
		/Slave: Error .* doesn't exist/ or
		/Slave: Error .*Deadlock found/ or
		/Slave: Error .*Unknown table/ or
		/Slave: Error in Write_rows event: / or
		/Slave: Field .* of table .* has no default value/ or
		/Slave: Query caused different errors on master and slave/ or
		/Slave: Table .* doesn't exist/ or
		/Slave: Table width mismatch/ or
		/Slave: The incident LOST_EVENTS occured on the master/ or
		/Slave: Unknown error.* 1105/ or
		/Slave: Can't drop database.* database doesn't exist/ or
		/Sort aborted/ or
		/Time-out in NDB/ or
		/Warning:\s+One can only use the --user.*root/ or
		/Warning:\s+Setting lower_case_table_names=2/ or
		/Warning:\s+Table:.* on (delete|rename)/ or
		/You have an error in your SQL syntax/ or
		/deprecated/ or
		/description of time zone/ or
		/equal MySQL server ids/ or
		/error .*connecting to master/ or
		/error reading log entry/ or
		/lower_case_table_names is set/ or
		/skip-name-resolve mode/ or
		/slave SQL thread aborted/ or
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
362
		/Slave: .*Duplicate entry/ or
363 364 365 366
		# Special case for Bug #26402 in show_check.test
		# Question marks are not valid file name parts
		# on Windows platforms. Ignore this error message. 
		/\QCan't find file: '.\test\????????.frm'\E/ or
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
367 368 369
		# Special case, made as specific as possible, for:
		# Bug #28436: Incorrect position in SHOW BINLOG EVENTS causes
		#             server coredump
370
		/\QError in Log_event::read_log_event(): 'Sanity check failed', data_len: 258, event_type: 49\E/ or
371
                /Statement is not safe to log in statement format/
372
	       )
373 374 375
            {
              next;                       # Skip these lines
            }
376 377 378 379
	    if ( /CURRENT_TEST: (.*)/ )
	    {
	      $testname= $1;
	    }
380 381
            if ( /$pattern/ )
            {
382 383 384
              if ($leak_reports_expected) {
                next;
              }
385
              $found_problems= 1;
386
              print WARN basename($errlog) . ": $testname: $_";
387 388 389 390
            }
          }
        }
      }
391

392
      if ( $::opt_check_testcases )
393
      {
394 395 396 397 398 399 400
        # Look for warnings produced by mysqltest in testname.warnings
        foreach my $test_warning_file
	  ( glob("$::glob_mysql_test_dir/r/*.warnings") )
        {
          $found_problems= 1;
	  print WARN "Check myqltest warnings in $test_warning_file\n";
        }
401 402
      }

403 404 405 406 407 408
      if ( $found_problems )
      {
	mtr_warning("Got errors/warnings while running tests, please examine",
		    "\"$warnlog\" for details.");
      }
    }
kent@mysql.com's avatar
kent@mysql.com committed
409 410 411 412
  }

  print "\n";

413
  # Print a list of testcases that failed
kent@mysql.com's avatar
kent@mysql.com committed
414 415
  if ( $tot_failed != 0 )
  {
416 417
    my $test_mode= join(" ", @::glob_test_mode) || "default";
    print "mysql-test-run in $test_mode mode: *** Failing the test(s):";
kent@mysql.com's avatar
kent@mysql.com committed
418 419 420 421 422 423 424 425 426

    foreach my $tinfo (@$tests)
    {
      if ( $tinfo->{'result'} eq 'MTR_RES_FAILED' )
      {
        print " $tinfo->{'name'}";
      }
    }
    print "\n";
427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448

  }

  # 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'} )
      {
	push(@check_testcases, $tinfo->{'name'});
      }
    }

    if ( @check_testcases )
    {
      print "Check of testcase failed for: ";
      print join(" ", @check_testcases);
      print "\n\n";
    }
449
  }
450

451 452
  if ( $tot_failed != 0 || $found_problems)
  {
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
453
    mtr_error("there were failing test cases");
kent@mysql.com's avatar
kent@mysql.com committed
454 455 456 457 458 459 460 461 462 463 464 465 466
  }
}

##############################################################################
#
#  Text formatting
#
##############################################################################

sub mtr_print_line () {
  print '-' x 55, "\n";
}

kent@mysql.com's avatar
kent@mysql.com committed
467 468 469 470
sub mtr_print_thick_line () {
  print '=' x 55, "\n";
}

kent@mysql.com's avatar
kent@mysql.com committed
471 472 473 474
sub mtr_print_header () {
  print "\n";
  if ( $::opt_timer )
  {
kent@mysql.com's avatar
kent@mysql.com committed
475
    print "TEST                           RESULT         TIME (ms)\n";
kent@mysql.com's avatar
kent@mysql.com committed
476 477 478
  }
  else
  {
kent@mysql.com's avatar
kent@mysql.com committed
479
    print "TEST                           RESULT\n";
kent@mysql.com's avatar
kent@mysql.com committed
480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500
  }
  mtr_print_line();
  print "\n";
}


##############################################################################
#
#  Misc
#
##############################################################################

sub mtr_report (@) {
  print join(" ", @_),"\n";
}

sub mtr_warning (@) {
  print STDERR "mysql-test-run: WARNING: ",join(" ", @_),"\n";
}

sub mtr_error (@) {
kent@mysql.com's avatar
kent@mysql.com committed
501 502
  print STDERR "mysql-test-run: *** ERROR: ",join(" ", @_),"\n";
  mtr_exit(1);
kent@mysql.com's avatar
kent@mysql.com committed
503 504
}

505 506 507 508 509
sub mtr_child_error (@) {
  print STDERR "mysql-test-run: *** ERROR(child): ",join(" ", @_),"\n";
  exit(1);
}

kent@mysql.com's avatar
kent@mysql.com committed
510 511 512
sub mtr_debug (@) {
  if ( $::opt_script_debug )
  {
kent@mysql.com's avatar
kent@mysql.com committed
513
    print STDERR "####: ",join(" ", @_),"\n";
kent@mysql.com's avatar
kent@mysql.com committed
514 515
  }
}
516 517 518 519 520 521
sub mtr_verbose (@) {
  if ( $::opt_verbose )
  {
    print STDERR "> ",join(" ", @_),"\n";
  }
}
kent@mysql.com's avatar
kent@mysql.com committed
522 523

1;