PS-6849: Backport MTR shutdown report implementation from 5.7

mysql/mysql-server@8aeda36

Bug#30909369: MTR DOES NOT NOTICE A SERVER ABORT AFTER "BYE"

Issue:
======
After a test is run, when the server is shutdown, MTR
does not detect the exit status of the shutdown, and
reports that the test passed, even if the server crashes.

Fix:
====
Added a shutdown_report for every run of tests, which
will report if the shutdown of the servers was successful
or not. The exit status of shutdown is monitored and if
a failure is found, the error log is parsed and the
shutdown_report will contain the errors.

This also fixes Bug#29818311, which reported the same
problem.

Change-Id: I4d8043915f9b085bfbd25e811c957cd0b4809454
(cherry picked from commit 8aeda36)

mysql-test/lib/My/SafeProcess.pm

@@ -1,5 +1,5 @@
 # -*- cperl -*-
-# Copyright (c) 2007, 2011, Oracle and/or its affiliates. All rights reserved.
+# Copyright (c) 2007, 2020, Oracle and/or its affiliates. All rights reserved.
 #
 # This program is free software; you can redistribute it and/or modify
 # it under the terms of the GNU General Public License, version 2.0,
@@ -228,6 +228,7 @@ sub shutdown {
   my $shutdown_timeout= shift;
   my @processes= @_;
   _verbose("shutdown, timeout: $shutdown_timeout, @processes");
+  my $shutdown_status = 0;
 
   return if (@processes == 0);
 
@@ -254,6 +255,9 @@ sub shutdown {
     my $ret= $proc->wait_one($shutdown_timeout);
     if ($ret != 0) {
       push(@kill_processes, $proc);
+    } else {
+      my $exit_status = $proc->exit_status();
+      $shutdown_status = $exit_status if $exit_status;
     }
     # Only wait for the first process with shutdown timeout
     $shutdown_timeout= 0;
@@ -272,7 +276,7 @@ sub shutdown {
   }
 
   # Return if all servers has exited
-  return if (@kill_processes == 0);
+  return $shutdown_status if (@kill_processes == 0);
 
   foreach my $proc (@kill_processes){
     $proc->start_kill();
@@ -282,7 +286,7 @@ sub shutdown {
     $proc->wait_one(undef);
   }
 
-  return;
+  return $shutdown_status;
 }
 
 

mysql-test/mysql-test-run.pl

@@ -325,6 +325,7 @@ sub set_term_args {
 our $opt_user = "root";
 
 our $opt_valgrind= 0;
+my $shutdown_report    = 0;
 my $opt_valgrind_mysqld= 0;
 my $opt_valgrind_mysqltest= 0;
 my @valgrind_args;
@@ -568,6 +569,26 @@ sub main {
 
   push @$completed, run_ctest() if $opt_ctest;
 
+  # Create minimalistic "test" for the reporting failures at shutdown
+  my $tinfo = My::Test->new(
+    name      => 'shutdown_report',
+    shortname => 'shutdown_report',
+    );
+
+  # Set dummy worker id to align report with normal tests
+  $tinfo->{worker} = 0 if $opt_parallel > 1;
+  if ($shutdown_report) {
+    $tinfo->{result} = 'MTR_RES_FAILED';
+    $tinfo->{comment} = "Mysqld reported failures at shutdown, see above";
+    $tinfo->{failures} = 1;
+  } else {
+    $tinfo->{result} = 'MTR_RES_PASSED';
+  }
+  mtr_report_test($tinfo);
+  report_option('prev_report_length', 0);
+  push @$completed, $tinfo;
+
+
   if ($opt_valgrind) {
     # Create minimalistic "test" for the reporting
     my $tinfo = My::Test->new
@@ -815,8 +836,10 @@ ($$$)
 	}
 	elsif ($line eq 'VALGREP' && $opt_valgrind) {
 	  $valgrind_reports= 1;
-	}
-	else {
+	} elsif ($line eq 'SRV_CRASH') {
+      # Mysqld detected crash during shutdown
+      $shutdown_report = 1;
+	} else {
 	  mtr_error("Unknown response: '$line' from client");
 	}
 
@@ -996,7 +1019,12 @@ ($)
     }
     elsif ($line eq 'BYE'){
       mtr_report("Server said BYE");
-      stop_all_servers($opt_shutdown_timeout);
+      my $ret = stop_all_servers($opt_shutdown_timeout);
+      if (defined $ret and $ret != 0) {
+        shutdown_exit_reports();
+        $shutdown_report = 1;
+      }
+      print $server "SRV_CRASH\n" if $shutdown_report;
       mark_time_used('restart');
       my $valgrind_reports= 0;
       if ($opt_valgrind_mysqld) {
@@ -1020,6 +1048,60 @@ ($)
   exit(1);
 }
 
+# Search server logs for any crashes during mysqld shutdown
+sub shutdown_exit_reports() {
+  my $found_report  = 0;
+  my $clean_shutdown = 0;
+
+  foreach my $log_file (keys %mysqld_logs) {
+    my @culprits = ();
+    my $crash_rep     = "";
+
+    my $LOGF = IO::File->new($log_file) or
+      mtr_error("Could not open file '$log_file' for reading: $!");
+
+    while (my $line = <$LOGF>) {
+      if ($line =~ /^CURRENT_TEST: (.+)$/) {
+        my $testname = $1;
+        # If we have a report, report it if needed and start new list of tests
+        if ($found_report or $clean_shutdown) {
+          # Make ready to collect new report
+          @culprits     = ();
+          $found_report = 0;
+          $clean_shutdown = 0;
+          $crash_rep = "";
+        }
+        push(@culprits, $testname);
+        next;
+      }
+
+      # Clean shutdown
+      $clean_shutdown = 1 if $line =~ /.*Shutdown completed.*/;
+
+      # Mysqld crash at shutdown
+      $found_report = 1 if ($line =~ /.*Assertion.*/ or $line =~ /.*mysqld got signal.*/
+                            or $line =~ /.*mysqld got exception.*/);
+
+      if ($found_report) {
+        $crash_rep .= $line;
+      }
+    }
+
+    if ($found_report) {
+        mtr_print("Shutdown report from $log_file after tests:\n", @culprits);
+        mtr_print_line();
+        print("$crash_rep\n");
+    } else {
+      # Print last 100 lines of log file since shutdown failed
+      # for some reason.
+      mtr_print("Shutdown report from $log_file after tests:\n", @culprits);
+      mtr_print_line();
+      my $reason = mtr_lastlinesfromfile($log_file, 100) . "\n";
+      print("$reason");
+    }
+    $LOGF = undef;
+  }
+}
 
 sub ignore_option {
   my ($opt, $value)= @_;
@@ -4513,7 +4595,11 @@ ($)
 	my $check_res;
 	if ( restart_forced_by_test('force_restart') )
 	{
-	  stop_all_servers($opt_shutdown_timeout);
+	  my $ret = stop_all_servers($opt_shutdown_timeout);
+      if ($ret != 0) {
+        shutdown_exit_reports();
+        $shutdown_report = 1;
+      }
 	}
 	elsif ( $opt_check_testcases and
 	     $check_res= check_testcase($tinfo, "after"))
@@ -5184,7 +5270,8 @@ ($)
     # In these cases we may want valgrind report from normal termination
     $tinfo->{'dont_kill_server'}= 1;
   }
-  # Shotdown properly if not to be killed (for valgrind)
+
+  # Shutdown properly if not to be killed (for valgrind)
   stop_all_servers($tinfo->{'dont_kill_server'} ? $opt_shutdown_timeout : 0);
 
   $tinfo->{'result'}= 'MTR_RES_FAILED';
@@ -5495,8 +5582,10 @@ ($$)
   unlink($mysqld->value('pid-file'));
 
   my $output= $mysqld->value('#log-error');
-  # Remember this log file for valgrind error report search
-  $mysqld_logs{$output}= 1 if $opt_valgrind;
+
+  # Remember this log file for valgrind/shutdown error report search
+  $mysqld_logs{$output} = 1;
+
   # Remember data dir for gmon.out files if using gprof
   $gprof_dirs{$mysqld->value('datadir')}= 1 if $opt_gprof;
 
@@ -5541,8 +5630,8 @@ ()
   mtr_verbose("Stopping all servers...");
 
   # Kill all started servers
-  My::SafeProcess::shutdown($shutdown_timeout,
-			    started(all_servers()));
+  my $ret = My::SafeProcess::shutdown($shutdown_timeout,
+			                          started(all_servers()));
 
   # Remove pidfiles
   foreach my $server ( all_servers() )
@@ -5552,8 +5641,8 @@ ()
   }
 
   # Mark servers as stopped
-  map($_->{proc}= undef, all_servers());
-
+  map($_->{proc} = undef, all_servers());
+  return $ret;
 }
 
 
@@ -5759,17 +5848,18 @@ ($$)
   my ($tinfo, @servers)= @_;
 
   # Remember if we restarted for this test case (count restarts)
-  $tinfo->{'restarted'}= 1;
+  $tinfo->{'restarted'} = 1;
+  my $ret;
 
   if ( join('|', @servers) eq join('|', all_servers()) )
   {
     # All servers are going down, use some kind of order to
     # avoid too many warnings in the log files
 
-   mtr_report("Restarting all servers");
+    mtr_report("Restarting all servers");
 
-    #  mysqld processes
-    My::SafeProcess::shutdown( $opt_shutdown_timeout, started(mysqlds()) );
+    # mysqld processes
+    $ret = My::SafeProcess::shutdown($opt_shutdown_timeout, started(mysqlds()));
 
     # cluster processes
     My::SafeProcess::shutdown( $opt_shutdown_timeout,
@@ -5779,9 +5869,14 @@ ($$)
   {
     mtr_report("Restarting ", started(@servers));
 
-     # Stop only some servers
-    My::SafeProcess::shutdown( $opt_shutdown_timeout,
-			       started(@servers) );
+    # Stop only some servers
+    my $ret = My::SafeProcess::shutdown($opt_shutdown_timeout,
+			                            started(@servers) );
+  }
+
+  if ($ret) {
+    shutdown_exit_reports();
+    $shutdown_report = 1;
   }
 
   foreach my $server (@servers)