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