diff --git a/mysql-test/lib/mtr_process.pl b/mysql-test/lib/mtr_process.pl index f5ef028fa24..a60b2822a14 100644 --- a/mysql-test/lib/mtr_process.pl +++ b/mysql-test/lib/mtr_process.pl @@ -99,25 +99,26 @@ sub spawn_impl ($$$$$$$) { if ( $::opt_script_debug ) { - print STDERR "\n"; - print STDERR "#### ", "-" x 78, "\n"; - print STDERR "#### ", "STDIN $input\n" if $input; - print STDERR "#### ", "STDOUT $output\n" if $output; - print STDERR "#### ", "STDERR $error\n" if $error; - print STDERR "#### ", "$mode : $path ", join(" ",@$arg_list_t), "\n"; - print STDERR "#### ", "spawn options:\n"; + mtr_report(""); + mtr_debug("-" x 73); + mtr_debug("STDIN $input") if $input; + mtr_debug("STDOUT $output") if $output; + mtr_debug("STDERR $error") if $error; + mtr_debug("$mode: $path ", join(" ",@$arg_list_t)); + mtr_debug("spawn options:"); if ($spawn_opts) { foreach my $key (sort keys %{$spawn_opts}) { - print STDERR "#### ", " - $key: $spawn_opts->{$key}\n"; + mtr_debug(" - $key: $spawn_opts->{$key}"); } } else { - print STDERR "#### ", " none\n"; + mtr_debug(" none"); } - print STDERR "#### ", "-" x 78, "\n"; + mtr_debug("-" x 73); + mtr_report(""); } mtr_error("Can't spawn with empty \"path\"") unless defined $path; diff --git a/mysql-test/lib/mtr_report.pl b/mysql-test/lib/mtr_report.pl index 1abfc6b6b57..0493ecad329 100644 --- a/mysql-test/lib/mtr_report.pl +++ b/mysql-test/lib/mtr_report.pl @@ -19,6 +19,7 @@ # same name. use strict; +use warnings; sub mtr_report_test_name($); sub mtr_report_test_passed($); @@ -97,6 +98,7 @@ sub mtr_show_failed_diff ($) { sub mtr_report_test_name ($) { my $tinfo= shift; + _mtr_log("$tinfo->{name}"); printf "%-30s ", $tinfo->{'name'}; } @@ -106,15 +108,15 @@ sub mtr_report_test_skipped ($) { $tinfo->{'result'}= 'MTR_RES_SKIPPED'; if ( $tinfo->{'disable'} ) { - print "[ disabled ] $tinfo->{'comment'}\n"; + mtr_report("[ disabled ] $tinfo->{'comment'}"); } elsif ( $tinfo->{'comment'} ) { - print "[ skipped ] $tinfo->{'comment'}\n"; + mtr_report("[ skipped ] $tinfo->{'comment'}"); } else { - print "[ skipped ]\n"; + mtr_report("[ skipped ]"); } } @@ -146,7 +148,7 @@ sub mtr_report_test_passed ($) { $timer= sprintf "%12s", $timer; } $tinfo->{'result'}= 'MTR_RES_PASSED'; - print "[ pass ] $timer\n"; + mtr_report("[ pass ] $timer"); } sub mtr_report_test_failed ($) { @@ -155,17 +157,17 @@ sub mtr_report_test_failed ($) { $tinfo->{'result'}= 'MTR_RES_FAILED'; if ( defined $tinfo->{'timeout'} ) { - print "[ fail ] timeout\n"; + mtr_report("[ fail ] timeout"); return; } else { - print "[ fail ]\n"; + mtr_report("[ fail ]"); } if ( $tinfo->{'comment'} ) { - print "\nERROR: $tinfo->{'comment'}\n"; + mtr_report("\nERROR: $tinfo->{'comment'}"); } elsif ( -f $::path_timefile ) { @@ -175,7 +177,7 @@ sub mtr_report_test_failed ($) { } else { - print "\nUnexpected termination, probably when starting mysqld\n"; + mtr_report("\nUnexpected termination, probably when starting mysqld");; } } @@ -243,8 +245,8 @@ sub mtr_report_stats ($) { if ( $::opt_timer ) { - print - "Spent $::glob_tot_real_time seconds actually executing testcases\n" + printf("Spent %.3f seconds actually executing testcases\n", + $::glob_tot_real_time); } # ---------------------------------------------------------------------- @@ -397,35 +399,66 @@ sub mtr_print_header () { ############################################################################## # -# Misc +# Log and reporting functions # ############################################################################## +use IO::File; + +my $log_file_ref= undef; + +sub mtr_log_init ($) { + my ($filename)= @_; + + mtr_error("Log is already open") if defined $log_file_ref; + + $log_file_ref= IO::File->new($filename, "a") or + mtr_warning("Could not create logfile $filename: $!"); +} + +sub _mtr_log (@) { + print $log_file_ref join(" ", @_),"\n" + if defined $log_file_ref; +} + sub mtr_report (@) { + # Print message to screen and log + _mtr_log(@_); print join(" ", @_),"\n"; } sub mtr_warning (@) { + # Print message to screen and log + _mtr_log("WARNING: ", @_); print STDERR "mysql-test-run: WARNING: ",join(" ", @_),"\n"; } sub mtr_error (@) { + # Print message to screen and log + _mtr_log("ERROR: ", @_); print STDERR "mysql-test-run: *** ERROR: ",join(" ", @_),"\n"; mtr_exit(1); } sub mtr_child_error (@) { + # Print message to screen and log + _mtr_log("ERROR(child): ", @_); print STDERR "mysql-test-run: *** ERROR(child): ",join(" ", @_),"\n"; exit(1); } sub mtr_debug (@) { + # Only print if --script-debug is used if ( $::opt_script_debug ) { + _mtr_log("###: ", @_); print STDERR "####: ",join(" ", @_),"\n"; } } + sub mtr_verbose (@) { + # Always print to log, print to screen only when --verbose is used + _mtr_log("> ",@_); if ( $::opt_verbose ) { print STDERR "> ",join(" ", @_),"\n"; diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl index c58ed308bd8..208127358c2 100755 --- a/mysql-test/mysql-test-run.pl +++ b/mysql-test/mysql-test-run.pl @@ -2891,6 +2891,9 @@ sub initialize_servers () { } } check_running_as_root(); + + mtr_log_init("$opt_vardir/log/mysql-test-run.log"); + } sub mysql_install_db () { @@ -3612,13 +3615,13 @@ sub report_failure_and_restart ($) { # Restore the snapshot of the installed test db restore_installed_db($tinfo->{'name'}); - print "Resuming Tests\n\n"; + mtr_report("Resuming Tests\n"); return; } my $test_mode= join(" ", @::glob_test_mode) || "default"; - print "Aborting: $tinfo->{'name'} failed in $test_mode mode. "; - print "To continue, re-run with '--force'.\n"; + mtr_report("Aborting: $tinfo->{'name'} failed in $test_mode mode. "); + mtr_report("To continue, re-run with '--force'."); if ( ! $glob_debugger and ! $opt_extern and ! $glob_use_embedded_server ) @@ -4076,11 +4079,11 @@ sub mysqld_start ($$$) { sub stop_all_servers () { - print "Stopping All Servers\n"; + mtr_report("Stopping All Servers"); if ( ! $opt_skip_im ) { - print "Shutting-down Instance Manager\n"; + mtr_report("Shutting-down Instance Manager"); unless (mtr_im_stop($instance_manager, "stop_all_servers")) { mtr_error("Failed to stop Instance Manager.")