mtr_report.pm 11.9 KB
Newer Older
kent@mysql.com's avatar
kent@mysql.com committed
1
# -*- cperl -*-
Luis Soares's avatar
Luis Soares committed
2
# Copyright 2004-2008 MySQL AB, 2008 Sun Microsystems, Inc.
3 4 5 6 7 8 9 10 11 12 13 14 15
# 
# 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

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

21
package mtr_report;
kent@mysql.com's avatar
kent@mysql.com committed
22
use strict;
23 24 25 26 27 28

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_verbose_restart mtr_report_test_passed
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
29
		mtr_report_test_skipped mtr_print
30
		mtr_report_test);
31

32
use mtr_match;
33 34
use My::Platform;
use POSIX qw[ _exit ];
35
require "mtr_io.pl";
kent@mysql.com's avatar
kent@mysql.com committed
36

37 38
my $tot_real_time= 0;

Magnus Svensson's avatar
Magnus Svensson committed
39
our $timestamp= 0;
40
our $timediff= 0;
41 42 43
our $name;
our $verbose;
our $verbose_restart= 0;
44
our $timer= 1;
45

46 47
sub report_option {
  my ($opt, $value)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
48

49 50 51
  # Evaluate $opt as string to use "Getopt::Long::Callback legacy API"
  my $opt_name = "$opt";

52
  # Convert - to _ in option name
53
  $opt_name =~ s/-/_/g;
54
  no strict 'refs';
55
  ${$opt_name}= $value;
56
}
kent@mysql.com's avatar
kent@mysql.com committed
57

58 59 60
sub _name {
  return $name ? $name." " : undef;
}
61 62

sub _mtr_report_test_name ($) {
kent@mysql.com's avatar
kent@mysql.com committed
63
  my $tinfo= shift;
64
  my $tname= $tinfo->{name};
kent@mysql.com's avatar
kent@mysql.com committed
65

66 67
  return unless defined $verbose;

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
68
  # Add combination name if any
69 70 71
  $tname.= " '$tinfo->{combination}'"
    if defined $tinfo->{combination};

72
  print _name(), _timestamp();
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
73
  printf "%-40s ", $tname;
74 75
  my $worker = $tinfo->{worker};
  printf "w$worker " if $worker;
76 77

  return $tname;
kent@mysql.com's avatar
kent@mysql.com committed
78 79
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
80

kent@mysql.com's avatar
kent@mysql.com committed
81
sub mtr_report_test_skipped ($) {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
82
  my ($tinfo)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
83
  $tinfo->{'result'}= 'MTR_RES_SKIPPED';
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
84 85

  mtr_report_test($tinfo);
86 87 88
}


89 90
sub mtr_report_test_passed ($) {
  my ($tinfo)= @_;
kent@mysql.com's avatar
kent@mysql.com committed
91

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
92
  # Save the timer value
93 94
  my $timer_str=  "";
  if ( $timer and -f "$::opt_vardir/log/timer" )
kent@mysql.com's avatar
kent@mysql.com committed
95
  {
96 97
    $timer_str= mtr_fromfile("$::opt_vardir/log/timer");
    $tinfo->{timer}= $timer_str;
kent@mysql.com's avatar
kent@mysql.com committed
98
  }
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
99

Magnus Svensson's avatar
Magnus Svensson committed
100 101 102 103
  # Big warning if status already set
  if ( $tinfo->{'result'} ){
    mtr_warning("mtr_report_test_passed: Test result",
		"already set to '", $tinfo->{'result'}, ",");
104
  }
105

Magnus Svensson's avatar
Magnus Svensson committed
106 107
  $tinfo->{'result'}= 'MTR_RES_PASSED';

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
108
  mtr_report_test($tinfo);
kent@mysql.com's avatar
kent@mysql.com committed
109 110
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
111

112 113
sub mtr_report_test ($) {
  my ($tinfo)= @_;
114
  my $test_name = _mtr_report_test_name($tinfo);
115

Daniel Fischer's avatar
Daniel Fischer committed
116 117 118 119
  my $comment=  $tinfo->{'comment'};
  my $logfile=  $tinfo->{'logfile'};
  my $warnings= $tinfo->{'warnings'};
  my $result=   $tinfo->{'result'};
120
  my $retry=    $tinfo->{'retries'} ? "retry-" : "";
121

122 123
  if ($result eq 'MTR_RES_FAILED'){

124
    my $timest = format_time();
125 126 127 128 129 130
    my $fail = "fail";

    if ( $::opt_experimental )
    {
      # Find out if this test case is an experimental one, so we can treat
      # the failure as an expected failure instead of a regression.
Daniel Fischer's avatar
Daniel Fischer committed
131
      for my $exp ( @$::experimental_test_cases ) {
132
        if ( $exp ne $test_name ) {
Daniel Fischer's avatar
Daniel Fischer committed
133 134 135
          # 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
136 137 138
          if ( $exp ne "" && substr($exp, -1, 1) eq "*" ) {
            $exp = substr($exp, 0, length($exp) - 1);
            if ( substr($test_name, 0, length($exp)) ne $exp ) {
Daniel Fischer's avatar
Daniel Fischer committed
139
              # no match, try next entry
140 141
              next;
            }
Daniel Fischer's avatar
Daniel Fischer committed
142
            # if yes, fall through to set the exp-fail status
143
          } else {
Daniel Fischer's avatar
Daniel Fischer committed
144
            # no match, try next entry
145 146 147 148 149 150 151
            next;
          }
        }
        $fail = "exp-fail";
        last;
      }
    }
152

153
    if ( $warnings )
154
    {
155
      mtr_report("[ $retry$fail ]  Found warnings/errors in server log file!");
156
      mtr_report("        Test ended at $timest");
157
      mtr_report($warnings);
158 159
      return;
    }
160 161
    my $timeout= $tinfo->{'timeout'};
    if ( $timeout )
162
    {
163
      mtr_report("[ $retry$fail ]  timeout after $timeout seconds");
164
      mtr_report("        Test ended at $timest");
165
      mtr_report("\n$tinfo->{'comment'}");
166 167 168 169
      return;
    }
    else
    {
170
      mtr_report("[ $retry$fail ]\n        Test ended at $timest");
171 172
    }

173 174 175 176 177 178 179
    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 )
180 181 182 183
    {
      # 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"
184
      mtr_report("\n$comment\n");
185 186
    }

187
    if ( !$logfile and !$comment )
188 189 190
    {
      # Neither this script or the test tool has recorded info
      # about why the test has failed. Should be debugged.
191
      mtr_report("\nUnknown result, neither 'comment' or 'logfile' set");
192 193
    }
  }
194
  elsif ($result eq 'MTR_RES_SKIPPED')
195 196 197
  {
    if ( $tinfo->{'disable'} )
    {
198
      mtr_report("[ disabled ]  $comment");
199
    }
200
    elsif ( $comment )
201
    {
202
      mtr_report("[ skipped ]  $comment");
203 204 205
    }
    else
    {
206
      mtr_report("[ skipped ]");
207 208
    }
  }
209
  elsif ($result eq 'MTR_RES_PASSED')
210
  {
211 212
    my $timer_str= $tinfo->{timer} || "";
    $tot_real_time += ($timer_str/1000);
213
    mtr_report("[ ${retry}pass ] ", sprintf("%5s", $timer_str));
214 215 216 217 218 219

    # Show any problems check-testcase found
    if ( defined $tinfo->{'check'} )
    {
      mtr_report($tinfo->{'check'});
    }
220 221 222 223
  }
}


kent@mysql.com's avatar
kent@mysql.com committed
224 225 226 227 228 229 230 231 232 233 234
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;
235
  my $tot_restarts= 0;
236
  my $found_problems= 0;
kent@mysql.com's avatar
kent@mysql.com committed
237 238 239

  foreach my $tinfo (@$tests)
  {
240
    if ( $tinfo->{failures} )
kent@mysql.com's avatar
kent@mysql.com committed
241
    {
242 243 244 245 246 247 248
      # Test has failed at least one time
      $tot_tests++;
      $tot_failed++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' )
    {
      # Test was skipped
kent@mysql.com's avatar
kent@mysql.com committed
249 250 251 252
      $tot_skiped++;
    }
    elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' )
    {
253
      # Test passed
kent@mysql.com's avatar
kent@mysql.com committed
254 255 256
      $tot_tests++;
      $tot_passed++;
    }
257

258 259
    if ( $tinfo->{'restarted'} )
    {
260
      # Servers was restarted
261 262
      $tot_restarts++;
    }
263

264 265 266 267 268 269 270 271 272 273 274
    # 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;
    }

275 276 277 278 279 280 281 282 283
    # 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'");
    }
kent@mysql.com's avatar
kent@mysql.com committed
284 285 286 287 288
  }

  # ----------------------------------------------------------------------
  # Print out a summary report to screen
  # ----------------------------------------------------------------------
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
289
  print "The servers were restarted $tot_restarts times\n";
290

291
  if ( $timer )
292
  {
293 294 295 296
    use English;

    mtr_report("Spent", sprintf("%.3f", $tot_real_time),"of",
	       time - $BASETIME, "seconds executing testcases");
297
  }
kent@mysql.com's avatar
kent@mysql.com committed
298 299


300 301
  my $warnlog= "$::opt_vardir/log/warnings";
  if ( -f $warnlog )
kent@mysql.com's avatar
kent@mysql.com committed
302
  {
303 304
    mtr_warning("Got errors/warnings while running tests, please examine",
		"'$warnlog' for details.");
Luis Soares's avatar
Luis Soares committed
305
 }
kent@mysql.com's avatar
kent@mysql.com committed
306 307 308

  print "\n";

309 310 311
  # Print a list of check_testcases that failed(if any)
  if ( $::opt_check_testcases )
  {
312
    my %check_testcases;
313 314 315 316 317

    foreach my $tinfo (@$tests)
    {
      if ( defined $tinfo->{'check_testcase_failed'} )
      {
318
	$check_testcases{$tinfo->{'name'}}= 1;
319 320 321
      }
    }

322
    if ( keys %check_testcases )
323 324
    {
      print "Check of testcase failed for: ";
325
      print join(" ", keys %check_testcases);
326 327
      print "\n\n";
    }
328
  }
329

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
330 331 332
  # Print a list of testcases that failed
  if ( $tot_failed != 0 )
  {
333 334 335

    # Print each failed test, again
    #foreach my $test ( @$tests ){
336
    #  if ( $test->{failures} ) {
337 338 339 340
    #    mtr_report_test($test);
    #  }
    #}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
341 342 343 344 345 346 347 348 349
    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):";

350
    my %seen= ();
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
351 352
    foreach my $tinfo (@$tests)
    {
353
      my $tname= $tinfo->{'name'};
354
      if ( ($tinfo->{failures} || $tinfo->{rep_failures}) and ! $seen{$tname})
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
355
      {
356 357
        print " $tname";
	$seen{$tname}= 1;
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
358 359 360 361 362 363 364 365 366 367 368 369 370 371
      }
    }
    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
  {
372
    print "All $tot_tests tests were successful.\n\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
373 374
  }

375 376
  if ( $tot_failed != 0 || $found_problems)
  {
tsmith@quadxeon.mysql.com's avatar
tsmith@quadxeon.mysql.com committed
377
    mtr_error("there were failing test cases");
kent@mysql.com's avatar
kent@mysql.com committed
378 379 380
  }
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
381

kent@mysql.com's avatar
kent@mysql.com committed
382 383 384 385 386 387 388
##############################################################################
#
#  Text formatting
#
##############################################################################

sub mtr_print_line () {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
389
  print '-' x 60, "\n";
kent@mysql.com's avatar
kent@mysql.com committed
390 391
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
392

393
sub mtr_print_thick_line {
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
394
  my $char= shift || '=';
395
  print $char x 78, "\n";
kent@mysql.com's avatar
kent@mysql.com committed
396 397
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
398

kent@mysql.com's avatar
kent@mysql.com committed
399 400
sub mtr_print_header () {
  print "\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
401 402 403 404 405
  printf "TEST";
  print " " x 38;
  print "RESULT   ";
  print "TIME (ms)" if $timer;
  print "\n";
kent@mysql.com's avatar
kent@mysql.com committed
406 407 408 409 410 411 412
  mtr_print_line();
  print "\n";
}


##############################################################################
#
413
#  Log and reporting functions
kent@mysql.com's avatar
kent@mysql.com committed
414 415 416
#
##############################################################################

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
417
use Time::localtime;
418

419 420
use Time::HiRes qw(gettimeofday);

421 422 423 424 425 426 427
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);
}

428 429
my $t0= gettimeofday();

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
430
sub _timestamp {
431
  return "" unless $timestamp;
432

433 434 435 436 437 438 439 440 441 442 443 444
  my $diff;
  if ($timediff){
    my $t1= gettimeofday();
    my $elapsed= $t1 - $t0;

    $diff= sprintf(" +%02.3f", $elapsed);

    # Save current time for next lap
    $t0= $t1;

  }

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
445
  my $tm= localtime();
446
  return sprintf("%02d%02d%02d %2d:%02d:%02d%s ",
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
447
		 $tm->year % 100, $tm->mon+1, $tm->mday,
448
		 $tm->hour, $tm->min, $tm->sec, $diff);
449 450
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
451 452
# Always print message to screen
sub mtr_print (@) {
453
  print _name(), join(" ", @_), "\n";
msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
454 455
}

456

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
457
# Print message to screen if verbose is defined
kent@mysql.com's avatar
kent@mysql.com committed
458
sub mtr_report (@) {
459 460
  if (defined $verbose)
  {
461
    print _name(), join(" ", @_), "\n";
462
  }
kent@mysql.com's avatar
kent@mysql.com committed
463 464
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
465

466
# Print warning to screen
kent@mysql.com's avatar
kent@mysql.com committed
467
sub mtr_warning (@) {
468
  print STDERR _name(), _timestamp(),
469
    "mysql-test-run: WARNING: ", join(" ", @_), "\n";
kent@mysql.com's avatar
kent@mysql.com committed
470 471 472
}


473
# Print error to screen and then exit
kent@mysql.com's avatar
kent@mysql.com committed
474
sub mtr_error (@) {
475
  print STDERR _name(), _timestamp(),
476
    "mysql-test-run: *** ERROR: ", join(" ", @_), "\n";
477 478 479 480 481 482 483 484
  if (IS_WINDOWS)
  {
    POSIX::_exit(1);
  }
  else
  {
    exit(1);
  }
485 486
}

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
487

kent@mysql.com's avatar
kent@mysql.com committed
488
sub mtr_debug (@) {
489
  if ( $verbose > 2 )
kent@mysql.com's avatar
kent@mysql.com committed
490
  {
491
    print STDERR _name(),
492
      _timestamp(), "####: ", join(" ", @_), "\n";
kent@mysql.com's avatar
kent@mysql.com committed
493 494
  }
}
495

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
496

497
sub mtr_verbose (@) {
498
  if ( $verbose )
499
  {
500
    print STDERR _name(), _timestamp(),
501
      "> ",join(" ", @_),"\n";
502 503
  }
}
kent@mysql.com's avatar
kent@mysql.com committed
504

msvensson@pilot.mysql.com's avatar
msvensson@pilot.mysql.com committed
505

506 507 508
sub mtr_verbose_restart (@) {
  my ($server, @args)= @_;
  my $proc= $server->{proc};
509
  if ( $verbose_restart )
510
  {
511
    print STDERR _name(),_timestamp(),
512
      "> Restart $proc - ",join(" ", @args),"\n";
513 514 515 516
  }
}


kent@mysql.com's avatar
kent@mysql.com committed
517
1;