Send output to var/log/mysql-test-run.log to facilitate easier debugging

of mysql-test-run.pl


mysql-test/lib/mtr_process.pl:
  Change from "print" to "mtr_debug" to get messages logged to file as well
mysql-test/lib/mtr_report.pl:
  - Add "mtr_log_init" function used for opening the log file
  - Change from "print" to "mtr_report" to get the messages logged
  - Make printout functions log to the log file
mysql-test/mysql-test-run.pl:
  - Open the mysql-test-run log file as soon as var/log has been created
  - Change from "print" to "mtr_report" to get the messgages to log as well

3 files changed, 63 insertions, 26 deletions

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.")