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