~drizzle-trunk/drizzle/development

1 by brian
clean slate
1
# -*- cperl -*-
2
# Copyright (C) 2004-2006 MySQL AB
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
21
use strict;
22
use warnings;
23
24
sub mtr_report_test_name($);
25
sub mtr_report_test_passed($);
26
sub mtr_report_test_failed($);
27
sub mtr_report_test_skipped($);
28
sub mtr_report_test_not_skipped_though_disabled($);
29
30
sub mtr_report_stats ($);
31
sub mtr_print_line ();
32
sub mtr_print_thick_line ();
33
sub mtr_print_header ();
34
sub mtr_report (@);
35
sub mtr_warning (@);
36
sub mtr_error (@);
37
sub mtr_child_error (@);
38
sub mtr_debug (@);
39
sub mtr_verbose (@);
40
41
my $tot_real_time= 0;
42
43
44
45
##############################################################################
46
#
47
#  
48
#
49
##############################################################################
50
51
sub mtr_report_test_name ($) {
52
  my $tinfo= shift;
53
  my $tname= $tinfo->{name};
54
55
  $tname.= " '$tinfo->{combination}'"
56
    if defined $tinfo->{combination};
57
58
  _mtr_log($tname);
1101.1.34 by Monty Taylor
Made subunit output optional.
59
  if ($::opt_subunit) {
60
    printf "test: $tname\n";
61
  } else {
62
    printf "%-30s ", $tname;
63
  }
1 by brian
clean slate
64
}
65
66
sub mtr_report_test_skipped ($) {
67
  my $tinfo= shift;
1103.3.1 by Robert Collins
First cut at subunit output.
68
  my $tname= $tinfo->{name};
69
  my $cause= "";
1 by brian
clean slate
70
71
  $tinfo->{'result'}= 'MTR_RES_SKIPPED';
72
  if ( $tinfo->{'disable'} )
73
  {
1103.3.1 by Robert Collins
First cut at subunit output.
74
    $cause.= "disable";
75
  }
76
  else
77
  {
78
    $cause.= "skipped";
79
  }
80
  if ( $tinfo->{'comment'} )
81
  {
1101.1.34 by Monty Taylor
Made subunit output optional.
82
    if ($::opt_subunit) {
83
      mtr_report("skip: $tname [\ncause: $cause\n$tinfo->{'comment'}\n]");
84
    } else { 
85
      mtr_report("[ $cause ]   $tinfo->{'comment'}");
86
    }
1103.3.1 by Robert Collins
First cut at subunit output.
87
  }
88
  else
89
  {
1101.1.34 by Monty Taylor
Made subunit output optional.
90
    if ($::opt_subunit) {
91
      mtr_report("skip: $tname");
92
    } else {
93
      mtr_report("[ $cause ]");
94
    }
1 by brian
clean slate
95
  }
96
}
97
98
sub mtr_report_tests_not_skipped_though_disabled ($) {
99
  my $tests= shift;
100
101
  if ( $::opt_enable_disabled )
102
  {
103
    my @disabled_tests= grep {$_->{'dont_skip_though_disabled'}} @$tests;
104
    if ( @disabled_tests )
105
    {
106
      print "\nTest(s) which will be run though they are marked as disabled:\n";
107
      foreach my $tinfo ( sort {$a->{'name'} cmp $b->{'name'}} @disabled_tests )
108
      {
109
        printf "  %-20s : %s\n", $tinfo->{'name'}, $tinfo->{'comment'};
110
      }
111
    }
112
  }
113
}
114
115
sub mtr_report_test_passed ($) {
116
  my $tinfo= shift;
1103.3.1 by Robert Collins
First cut at subunit output.
117
  my $tname= $tinfo->{name};
1 by brian
clean slate
118
119
  my $timer=  "";
120
  if ( $::opt_timer and -f "$::opt_vardir/log/timer" )
121
  {
122
    $timer= mtr_fromfile("$::opt_vardir/log/timer");
123
    $tot_real_time += ($timer/1000);
124
    $timer= sprintf "%12s", $timer;
1103.3.1 by Robert Collins
First cut at subunit output.
125
    ### XXX: How to format this as iso6801 datetime?
1 by brian
clean slate
126
  }
127
  $tinfo->{'result'}= 'MTR_RES_PASSED';
1101.1.34 by Monty Taylor
Made subunit output optional.
128
  if ($::opt_subunit) {
129
    mtr_report("success: $tname");
130
  } else {
131
    mtr_report("[ pass ]   $timer");
132
  }
1 by brian
clean slate
133
}
134
135
sub mtr_report_test_failed ($) {
136
  my $tinfo= shift;
1103.3.1 by Robert Collins
First cut at subunit output.
137
  my $tname= $tinfo->{name};
138
  my $comment= "";
1 by brian
clean slate
139
140
  $tinfo->{'result'}= 'MTR_RES_FAILED';
141
  if ( defined $tinfo->{'timeout'} )
142
  {
1103.3.1 by Robert Collins
First cut at subunit output.
143
    $comment.= "timeout";
144
  }
145
  elsif ( $tinfo->{'comment'} )
1 by brian
clean slate
146
  {
147
    # The test failure has been detected by mysql-test-run.pl
148
    # when starting the servers or due to other error, the reason for
149
    # failing the test is saved in "comment"
1103.3.1 by Robert Collins
First cut at subunit output.
150
    $comment.= "$tinfo->{'comment'}";
1 by brian
clean slate
151
  }
152
  elsif ( -f $::path_timefile )
153
  {
154
    # Test failure was detected by test tool and it's report
155
    # about what failed has been saved to file. Display the report.
1103.3.1 by Robert Collins
First cut at subunit output.
156
    $comment.= mtr_fromfile($::path_timefile);
1 by brian
clean slate
157
  }
158
  else
159
  {
160
    # Neither this script or the test tool has recorded info
161
    # about why the test has failed. Should be debugged.
1103.3.1 by Robert Collins
First cut at subunit output.
162
    $comment.= "Unexpected termination, probably when starting mysqld";
1 by brian
clean slate
163
  }
1101.1.34 by Monty Taylor
Made subunit output optional.
164
  if ($::opt_subunit) {
165
    mtr_report("failure: $tname [\n$comment\n]");
166
  } else {
167
    mtr_report("[ fail ]   $comment");
168
  }
1 by brian
clean slate
169
}
170
171
sub mtr_report_stats ($) {
172
  my $tests= shift;
173
174
  # ----------------------------------------------------------------------
175
  # Find out how we where doing
176
  # ----------------------------------------------------------------------
177
178
  my $tot_skiped= 0;
179
  my $tot_passed= 0;
180
  my $tot_failed= 0;
181
  my $tot_tests=  0;
182
  my $tot_restarts= 0;
183
  my $found_problems= 0; # Some warnings in the logfiles are errors...
184
185
  foreach my $tinfo (@$tests)
186
  {
187
    if ( $tinfo->{'result'} eq 'MTR_RES_SKIPPED' )
188
    {
189
      $tot_skiped++;
190
    }
191
    elsif ( $tinfo->{'result'} eq 'MTR_RES_PASSED' )
192
    {
193
      $tot_tests++;
194
      $tot_passed++;
195
    }
196
    elsif ( $tinfo->{'result'} eq 'MTR_RES_FAILED' )
197
    {
198
      $tot_tests++;
199
      $tot_failed++;
200
    }
201
    if ( $tinfo->{'restarted'} )
202
    {
203
      $tot_restarts++;
204
    }
205
  }
206
207
  # ----------------------------------------------------------------------
208
  # Print out a summary report to screen
209
  # ----------------------------------------------------------------------
210
211
  if ( ! $tot_failed )
212
  {
213
    print "All $tot_tests tests were successful.\n";
214
  }
215
  else
216
  {
217
    my $ratio=  $tot_passed * 100 / $tot_tests;
218
    print "Failed $tot_failed/$tot_tests tests, ";
219
    printf("%.2f", $ratio);
220
    print "\% were successful.\n\n";
221
    print
222
      "The log files in var/log may give you some hint\n",
223
      "of what went wrong.\n",
873.2.7 by Monty Taylor
Fixed error message.
224
      "If you want to report this error, go to:\n",
225
      "\thttp://bugs.launchpad.net/drizzle\n";
1 by brian
clean slate
226
  }
227
  if (!$::opt_extern)
228
  {
229
    print "The servers were restarted $tot_restarts times\n";
230
  }
231
232
  if ( $::opt_timer )
233
  {
234
    use English;
235
236
    mtr_report("Spent", sprintf("%.3f", $tot_real_time),"of",
237
	       time - $BASETIME, "seconds executing testcases");
238
  }
239
240
  # ----------------------------------------------------------------------
241
  # If a debug run, there might be interesting information inside
242
  # the "var/log/*.err" files. We save this info in "var/log/warnings"
243
  # ----------------------------------------------------------------------
244
245
  if ( ! $::glob_use_running_server )
246
  {
247
    # Save and report if there was any fatal warnings/errors in err logs
248
249
    my $warnlog= "$::opt_vardir/log/warnings";
250
251
    unless ( open(WARN, ">$warnlog") )
252
    {
253
      mtr_warning("can't write to the file \"$warnlog\": $!");
254
    }
255
    else
256
    {
257
      # We report different types of problems in order
258
      foreach my $pattern ( "^Warning:",
259
			    "\\[Warning\\]",
260
			    "\\[ERROR\\]",
261
			    "^Error:", "^==.* at 0x",
262
			    "InnoDB: Warning",
263
			    "InnoDB: Error",
264
			    "^safe_mutex:",
265
			    "missing DBUG_RETURN",
266
			    "mysqld: Warning",
267
			    "allocated at line",
268
			    "Attempting backtrace", "Assertion .* failed" )
269
      {
270
        foreach my $errlog ( sort glob("$::opt_vardir/log/*.err") )
271
        {
272
	  my $testname= "";
273
          unless ( open(ERR, $errlog) )
274
          {
275
            mtr_warning("can't read $errlog");
276
            next;
277
          }
278
          my $leak_reports_expected= undef;
279
          while ( <ERR> )
280
          {
281
            # There is a test case that purposely provokes a
282
            # SAFEMALLOC leak report, even though there is no actual
283
            # leak. We need to detect this, and ignore the warning in
284
            # that case.
285
            if (/Begin safemalloc memory dump:/) {
286
              $leak_reports_expected= 1;
287
            } elsif (/End safemalloc memory dump./) {
288
              $leak_reports_expected= undef;
289
            }
290
291
            # Skip some non fatal warnings from the log files
292
            if (
293
		/\"SELECT UNIX_TIMESTAMP\(\)\" failed on master/ or
294
		/Aborted connection/ or
295
		/Client requested master to start replication from impossible position/ or
296
		/Could not find first log file name in binary log/ or
297
		/Enabling keys got errno/ or
298
		/Error reading master configuration/ or
299
		/Error reading packet/ or
300
		/Event Scheduler/ or
301
		/Failed to open log/ or
302
		/Failed to open the existing master info file/ or
303
		/Forcing shutdown of [0-9]* plugins/ or
304
                /Can't open shared library .*\bha_example\b/ or
305
                /Couldn't load plugin .*\bha_example\b/ or
306
307
		# Due to timing issues, it might be that this warning
308
		# is printed when the server shuts down and the
309
		# computer is loaded.
310
		/Forcing close of thread \d+  user: '.*?'/ or
311
312
		/Got error [0-9]* when reading table/ or
313
		/Incorrect definition of table/ or
314
		/Incorrect information in file/ or
315
		/InnoDB: Warning: we did not need to do crash recovery/ or
316
		/Invalid \(old\?\) table or database name/ or
317
		/Lock wait timeout exceeded/ or
318
		/Log entry on master is longer than max_allowed_packet/ or
319
                /unknown option '--loose-/ or
320
                /unknown variable 'loose-/ or
321
		/You have forced lower_case_table_names to 0 through a command-line option/ or
322
		/Setting lower_case_table_names=2/ or
323
		/NDB Binlog:/ or
324
		/NDB: failed to setup table/ or
325
		/NDB: only row based binary logging/ or
326
		/Neither --relay-log nor --relay-log-index were used/ or
327
		/Query partially completed/ or
328
		/Slave I.O thread aborted while waiting for relay log/ or
329
		/Slave SQL thread is stopped because UNTIL condition/ or
330
		/Slave SQL thread retried transaction/ or
331
		/Slave \(additional info\)/ or
332
		/Slave: .*Duplicate column name/ or
333
		/Slave: .*master may suffer from/ or
334
		/Slave: According to the master's version/ or
335
		/Slave: Column [0-9]* type mismatch/ or
336
                /Slave: Can't DROP 'c7'; check that column.key exists Error_code: 1091/ or
337
                /Slave: Unknown column 'c7' in 't15' Error_code: 1054/ or
338
                /Slave: Key column 'c6' doesn't exist in table Error_code: 1072/ or
339
		/Slave: Error .* doesn't exist/ or
340
		/Slave: Error .*Deadlock found/ or
341
		/Slave: Error .*Unknown table/ or
342
		/Slave: Error in Write_rows event: / or
343
		/Slave: Field .* of table .* has no default value/ or
344
                /Slave: Field .* doesn't have a default value/ or
345
		/Slave: Query caused different errors on master and slave/ or
346
		/Slave: Table .* doesn't exist/ or
347
		/Slave: Table width mismatch/ or
348
		/Slave: The incident LOST_EVENTS occured on the master/ or
349
		/Slave: Unknown error.* 1105/ or
350
		/Slave: Can't drop database.* database doesn't exist/ or
351
                /Slave SQL:.*(?:Error_code: \d+|Query:.*)/ or
352
		
353
		# backup_errors test is supposed to trigger lots of backup related errors
354
		($testname eq 'main.backup_errors') and
355
		(
356
		  /Backup:/ or /Restore:/ or /Can't open the online backup progress tables/
357
		) or
358
		# The tablespace test triggers error below on purpose
359
		($testname eq 'main.backup_tablespace') and
360
		(
361
		  /Restore: Tablespace .* needed by tables being restored has changed on the server/
362
		) or
363
		
364
		/Sort aborted/ or
365
		/Time-out in NDB/ or
366
		/One can only use the --user.*root/ or
367
		/Setting lower_case_table_names=2/ or
368
		/Table:.* on (delete|rename)/ or
369
		/You have an error in your SQL syntax/ or
370
		/deprecated/ or
371
		/description of time zone/ or
372
		/equal MySQL server ids/ or
373
		/error .*connecting to master/ or
374
		/error reading log entry/ or
375
		/lower_case_table_names is set/ or
376
		/skip-name-resolve mode/ or
377
		/slave SQL thread aborted/ or
378
		/Slave: .*Duplicate entry/ or
379
		# Special case for Bug #26402 in show_check.test
380
		# Question marks are not valid file name parts
381
		# on Windows platforms. Ignore this error message. 
382
		/\QCan't find file: '.\test\????????.frm'\E/ or
383
		# Special case, made as specific as possible, for:
384
		# Bug #28436: Incorrect position in SHOW BINLOG EVENTS causes
385
		#             server coredump
386
		/\QError in Log_event::read_log_event(): 'Sanity check failed', data_len: 258, event_type: 49\E/ or
387
                /Statement is not safe to log in statement format/ or
388
389
                # test case for Bug#bug29807 copies a stray frm into database
390
                /InnoDB: Error: table `test`.`bug29807` does not exist in the InnoDB internal/ or
391
                /Cannot find or open table test\/bug29807 from/ or
392
393
                # innodb foreign key tests that fail in ALTER or RENAME produce this
394
                /InnoDB: Error: in ALTER TABLE `test`.`t[12]`/ or
395
                /InnoDB: Error: in RENAME TABLE table `test`.`t1`/ or
396
                /InnoDB: Error: table `test`.`t[12]` does not exist in the InnoDB internal/ or
397
398
                # Test case for Bug#14233 produces the following warnings:
399
                /Stored routine 'test'.'bug14233_1': invalid value in column mysql.proc/ or
400
                /Stored routine 'test'.'bug14233_2': invalid value in column mysql.proc/ or
401
                /Stored routine 'test'.'bug14233_3': invalid value in column mysql.proc/ or
402
403
                # BUG#29839 - lowercase_table3.test: Cannot find table test/T1
404
                #             from the internal data dictiona
405
                /Cannot find table test\/BUG29839 from the internal data dictionary/ or
406
                # BUG#32080 - Excessive warnings on Solaris: setrlimit could not
407
                #             change the size of core files
408
                /setrlimit could not change the size of core files to 'infinity'/ or
409
410
                # rpl_ndb_basic expects this error
411
                /Slave: Got error 146 during COMMIT Error_code: 1180/ or
412
413
		# rpl_extrColmaster_*.test, the slave thread produces warnings
414
		# when it get updates to a table that has more columns on the
415
		# master
416
		/Slave: Unknown column 'c7' in 't15' Error_code: 1054/ or
417
		/Slave: Can't DROP 'c7'.* 1091/ or
418
		/Slave: Key column 'c6'.* 1072/ or
419
420
                # BUG#32080 - Excessive warnings on Solaris: setrlimit could not
421
                #             change the size of core files
422
                /setrlimit could not change the size of core files to 'infinity'/ or
423
		# rpl_idempotency.test produces warnings for the slave.
424
		($testname eq 'rpl.rpl_idempotency' and
425
		 (/Slave: Can\'t find record in \'t1\' Error_code: 1032/ or
426
                  /Slave: Cannot add or update a child row: a foreign key constraint fails .* Error_code: 1452/
427
		 )) or
428
429
		# These tests does "kill" on queries, causing sporadic errors when writing to logs
430
		(($testname eq 'rpl.rpl_skip_error' or
431
		  $testname eq 'rpl.rpl_err_ignoredtable' or
432
		  $testname eq 'binlog.binlog_killed_simulate' or
433
		  $testname eq 'binlog.binlog_killed') and
434
		 (/Failed to write to mysql\.\w+_log/
435
		 )) or
436
437
		# rpl_bug33931 has deliberate failures
438
		($testname eq 'rpl.rpl_bug33931' and
439
		 (/Failed during slave.*thread initialization/
440
		  )) or
441
442
		# rpl_temporary has an error on slave that can be ignored
443
		($testname eq 'rpl.rpl_temporary' and
444
		 (/Slave: Can\'t find record in \'user\' Error_code: 1032/
445
		 )) or
446
447
                # Test case for Bug#31590 produces the following error:
448
                /Out of sort memory; increase server sort buffer size/
449
		)
450
            {
451
              next;                       # Skip these lines
452
            }
453
	    if ( /CURRENT_TEST: (.*)/ )
454
	    {
455
	      $testname= $1;
456
	    }
457
            if ( /$pattern/ )
458
            {
459
              if ($leak_reports_expected) {
460
                next;
461
              }
462
              $found_problems= 1;
463
              print WARN basename($errlog) . ": $testname: $_";
464
            }
465
          }
466
        }
467
      }
468
469
      if ( $::opt_check_testcases )
470
      {
471
        # Look for warnings produced by mysqltest in testname.warnings
472
        foreach my $test_warning_file
473
	  ( glob("$::glob_mysql_test_dir/r/*.warnings") )
474
        {
475
          $found_problems= 1;
476
	  print WARN "Check myqltest warnings in $test_warning_file\n";
477
        }
478
      }
479
480
      if ( $found_problems )
481
      {
482
	mtr_warning("Got errors/warnings while running tests, please examine",
483
		    "\"$warnlog\" for details.");
484
      }
485
    }
486
  }
487
488
  print "\n";
489
490
  # Print a list of testcases that failed
491
  if ( $tot_failed != 0 )
492
  {
493
    my $test_mode= join(" ", @::glob_test_mode) || "default";
494
    print "mysql-test-run in $test_mode mode: *** Failing the test(s):";
495
496
    foreach my $tinfo (@$tests)
497
    {
498
      if ( $tinfo->{'result'} eq 'MTR_RES_FAILED' )
499
      {
500
        print " $tinfo->{'name'}";
501
      }
502
    }
503
    print "\n";
504
505
  }
506
507
  # Print a list of check_testcases that failed(if any)
508
  if ( $::opt_check_testcases )
509
  {
510
    my @check_testcases= ();
511
512
    foreach my $tinfo (@$tests)
513
    {
514
      if ( defined $tinfo->{'check_testcase_failed'} )
515
      {
516
	push(@check_testcases, $tinfo->{'name'});
517
      }
518
    }
519
520
    if ( @check_testcases )
521
    {
522
      print "Check of testcase failed for: ";
523
      print join(" ", @check_testcases);
524
      print "\n\n";
525
    }
526
  }
527
528
  if ( $tot_failed != 0 || $found_problems)
529
  {
530
    mtr_error("there were failing test cases");
531
  }
532
}
533
534
##############################################################################
535
#
536
#  Text formatting
537
#
538
##############################################################################
539
540
sub mtr_print_line () {
541
  print '-' x 55, "\n";
542
}
543
544
sub mtr_print_thick_line () {
545
  print '=' x 55, "\n";
546
}
547
548
sub mtr_print_header () {
496.1.1 by Paul McCullagh
Added --engine option to drizzle-test-run (default innodb)
549
  print "DEFAULT STORAGE ENGINE: $::opt_engine\n";
1 by brian
clean slate
550
  if ( $::opt_timer )
551
  {
552
    print "TEST                           RESULT         TIME (ms)\n";
553
  }
554
  else
555
  {
556
    print "TEST                           RESULT\n";
557
  }
558
  mtr_print_line();
559
  print "\n";
560
}
561
562
563
##############################################################################
564
#
565
#  Log and reporting functions
566
#
567
##############################################################################
568
569
use IO::File;
570
571
my $log_file_ref= undef;
572
573
sub mtr_log_init ($) {
574
  my ($filename)= @_;
575
576
  mtr_error("Log is already open") if defined $log_file_ref;
577
578
  $log_file_ref= IO::File->new($filename, "a") or
579
    mtr_warning("Could not create logfile $filename: $!");
580
}
581
582
sub _mtr_log (@) {
583
  print $log_file_ref join(" ", @_),"\n"
584
    if defined $log_file_ref;
585
}
586
587
sub mtr_report (@) {
588
  # Print message to screen and log
589
  _mtr_log(@_);
590
  print join(" ", @_),"\n";
591
}
592
593
sub mtr_warning (@) {
594
  # Print message to screen and log
595
  _mtr_log("WARNING: ", @_);
596
  print STDERR "mysql-test-run: WARNING: ",join(" ", @_),"\n";
597
}
598
599
sub mtr_error (@) {
600
  # Print message to screen and log
601
  _mtr_log("ERROR: ", @_);
602
  print STDERR "mysql-test-run: *** ERROR: ",join(" ", @_),"\n";
603
  mtr_exit(1);
604
}
605
606
sub mtr_child_error (@) {
607
  # Print message to screen and log
608
  _mtr_log("ERROR(child): ", @_);
609
  print STDERR "mysql-test-run: *** ERROR(child): ",join(" ", @_),"\n";
610
  exit(1);
611
}
612
613
sub mtr_debug (@) {
614
  # Only print if --script-debug is used
615
  if ( $::opt_script_debug )
616
  {
617
    _mtr_log("###: ", @_);
618
    print STDERR "####: ",join(" ", @_),"\n";
619
  }
620
}
621
622
sub mtr_verbose (@) {
623
  # Always print to log, print to screen only when --verbose is used
624
  _mtr_log("> ",@_);
625
  if ( $::opt_verbose )
626
  {
627
    print STDERR "> ",join(" ", @_),"\n";
628
  }
629
}
630
631
1;