maria-developers team mailing list archive

[knielsen@xxxxxxxxxxxxxxx]

#At lp:maria

 2684 knielsen@xxxxxxxxxxxxxxx	2009-03-17
      BUG#43418: MTR2: does not notice a memory leak occuring at shutdown of
      mysqld w/ --valgrind
      
      Problem was that mysql-test-run.pl sometimes skipped parsing part of
      the error log, and sometimes shutdown mysqld with kill -9, preventing
      tools like Valgrind and safemalloc from outputting memory leak check
      in the error logs.
      
      Fixed by
      
       - Stopping mysqld servers gracefully rather than kill -9 when
         warnings are being checked.
      
       - After stopping mysqld servers, do an additional parse of the error
         log to check for any warnings generated during shutdown.
      
       - Fix error log parsing to be careful not to skip parsing part of the
         file, by keeping track of previous file position rather than
         relying on mark_log markers.
      
       - Workers report warnings during shutdown to the master process with
         a new packet 'WARNINGS' which includes a list of names of test that
         might have caused the problem (could be any test run since last
         server start).
      
       - Fail entire test suite if warnings are found.
      
      Also fixed home-brewed and broken serialization in My::Test to use the
      standard Storable serializer.
modified:
  mysql-test/lib/My/Test.pm
  mysql-test/mysql-test-run.pl

=== modified file 'mysql-test/lib/My/Test.pm'
--- a/mysql-test/lib/My/Test.pm	2008-11-14 10:49:12 +0000
+++ b/mysql-test/lib/My/Test.pm	2009-03-17 08:23:05 +0000
@@ -9,6 +9,7 @@ package My::Test;
 use strict;
 use warnings;
 use Carp;
+use Storable();
 
 
 sub new {
@@ -30,18 +31,6 @@ sub key {
 }
 
 
-sub _encode {
-  my ($value)= @_;
-  $value =~ s/([|\\\x{0a}\x{0d}])/sprintf('\%02X', ord($1))/eg;
-  return $value;
-}
-
-sub _decode {
-  my ($value)= @_;
-  $value =~ s/\\([0-9a-fA-F]{2})/chr(hex($1))/ge;
-  return $value;
-}
-
 sub is_failed {
   my ($self)= @_;
   my $result= $self->{result};
@@ -58,66 +47,22 @@ sub write_test {
   # Give the test a unique key before serializing it
   $test->{key}= "$test" unless defined $test->{key};
 
-  print $sock $header, "\n";
-  while ((my ($key, $value)) = each(%$test)) {
-    print $sock  $key, "= ";
-    if (ref $value eq "ARRAY") {
-      print $sock "[", _encode(join(", ", @$value)), "]";
-    } else {
-      print $sock _encode($value);
-    }
-    print $sock "\n";
-  }
-  print $sock "\n";
+  my $serialized= Storable::freeze($test);
+  $serialized =~ s/([\x0d\x0a\\])/sprintf("\\%02x", ord($1))/eg;
+  print $sock $header, "\n", $serialized, "\n";
 }
 
 
 sub read_test {
   my ($sock)= @_;
-  my $test= My::Test->new();
-  # Read the : separated key value pairs until a
-  # single newline on it's own line
-  my $line;
-  while (defined($line= <$sock>)) {
-    # List is terminated by newline on it's own
-    if ($line eq "\n") {
-      # Correctly terminated reply
-      # print "Got newline\n";
-      last;
-    }
-    chomp($line);
-
-    # Split key/value on the first "="
-    my ($key, $value)= split("= ", $line, 2);
-
-    if ($value =~ /^\[(.*)\]/){
-      my @values= split(", ", _decode($1));
-      push(@{$test->{$key}}, @values);
-    }
-    else
-    {
-      $test->{$key}= _decode($value);
-    }
-  }
+  my $serialized= <$sock>;
+  chomp($serialized);
+  $serialized =~ s/\\([0-9a-fA-F]{2})/chr(hex($1))/eg;
+  my $test= Storable::thaw($serialized);
+  die "wrong class (hack attempt?)"
+    unless ref($test) eq 'My::Test';
   return $test;
 }
 
 
-sub print_test {
-  my ($self)= @_;
-
-  print "[", $self->{name}, "]", "\n";
-  while ((my ($key, $value)) = each(%$self)) {
-    print " ", $key, "= ";
-    if (ref $value eq "ARRAY") {
-      print "[", join(", ", @$value), "]";
-    } else {
-      print $value;
-    }
-    print "\n";
-  }
-  print "\n";
-}
-
-
 1;

=== modified file 'mysql-test/mysql-test-run.pl'
--- a/mysql-test/mysql-test-run.pl	2009-03-12 22:27:35 +0000
+++ b/mysql-test/mysql-test-run.pl	2009-03-17 08:23:05 +0000
@@ -357,7 +357,7 @@ sub main {
   mtr_print_thick_line();
   mtr_print_header();
 
-  my $completed= run_test_server($server, $tests, $opt_parallel);
+  my ($completed, $fail)= run_test_server($server, $tests, $opt_parallel);
 
   # Send Ctrl-C to any children still running
   kill("INT", keys(%children));
@@ -393,6 +393,10 @@ sub main {
     mtr_error("Not all tests completed");
   }
 
+  if ($fail) {
+    mtr_error("Test suite failure.");
+  }
+
   mtr_print_line();
 
   if ( $opt_gcov ) {
@@ -412,6 +416,7 @@ sub run_test_server ($$$) {
   my $num_saved_cores= 0;  # Number of core files saved in vardir/log/ so far.
   my $num_saved_datadir= 0;  # Number of datadirs saved in vardir/log/ so far.
   my $num_failed_test= 0; # Number of tests failed so far
+  my $test_failure= 0;
 
   # Scheduler variables
   my $max_ndb= $childs / 2;
@@ -445,7 +450,7 @@ sub run_test_server ($$$) {
 	  $s->remove($sock);
 	  if (--$childs == 0){
 	    $suite_timeout_proc->kill();
-	    return $completed;
+	    return ($completed, $test_failure);
 	  }
 	  next;
 	}
@@ -509,18 +514,19 @@ sub run_test_server ($$$) {
 	    }
 	    $num_saved_datadir++;
 
+            $test_failure= 1;
 	    if ( !$opt_force ) {
 	      # Test has failed, force is off
 	      $suite_timeout_proc->kill();
 	      push(@$completed, $result);
-	      return $completed;
+	      return ($completed, 1);
 	    }
 	    elsif ($opt_max_test_fail > 0 and
 		   $num_failed_test >= $opt_max_test_fail) {
 	      $suite_timeout_proc->kill();
 	      mtr_report("Too many tests($num_failed_test) failed!",
 			 "Terminating...");
-	      return undef;
+	      return (undef, 1);
 	    }
 	    $num_failed_test++;
 	  }
@@ -571,7 +577,18 @@ sub run_test_server ($$$) {
 	elsif ($line eq 'START'){
 	  ; # Send first test
 	}
-	else {
+	elsif ($line eq 'WARNINGS'){
+          my $fake_test= My::Test::read_test($sock);
+          my $test_list= join (" ", @{$fake_test->{testnames}});
+          mtr_report("***Warnings generated in error logs during shutdown ".
+                     "after running tests: $test_list");
+          $test_failure= 1;
+          if ( !$opt_force ) {
+            # Test failure due to warnings, force is off
+            $suite_timeout_proc->kill();
+            return ($completed, 1);
+          }
+        } else {
 	  mtr_error("Unknown response: '$line' from client");
 	}
 
@@ -649,7 +666,7 @@ sub run_test_server ($$$) {
     if ( ! $suite_timeout_proc->wait_one(0) )
     {
       mtr_report("Test suite timeout! Terminating...");
-      return undef;
+      return (undef, 1);
     }
   }
 }
@@ -717,7 +734,7 @@ sub run_worker ($) {
       delete($test->{'comment'});
       delete($test->{'logfile'});
 
-      run_testcase($test);
+      run_testcase($test, $server);
       #$test->{result}= 'MTR_RES_PASSED';
       # Send it back, now with results set
       #$test->print_test();
@@ -725,6 +742,15 @@ sub run_worker ($) {
     }
     elsif ($line eq 'BYE'){
       mtr_report("Server said BYE");
+      # We need to gracefully shut down the servers to see any
+      # Valgrind memory leak errors etc. since last server restart.
+      if ($opt_warnings) {
+        stop_servers(all_servers());
+        if(check_warnings_post_shutdown($server)) {
+          # Warnings appeared in log file(s) during final server shutdown.
+          exit(1);
+        }
+      }
       exit(0);
     }
     else {
@@ -732,8 +758,8 @@ sub run_worker ($) {
     }
   }
 
+  # NOTREACHED
   stop_all_servers();
-
   exit(1);
 }
 
@@ -3109,6 +3135,7 @@ sub run_on_all($$)
 sub mark_log {
   my ($log, $tinfo)= @_;
   my $log_msg= "CURRENT_TEST: $tinfo->{name}\n";
+  pre_write_errorlog($log, $tinfo->{name});
   mtr_tofile($log, $log_msg);
 }
 
@@ -3181,8 +3208,8 @@ my %old_env;
 #  > 0 failure
 #
 
-sub run_testcase ($) {
-  my $tinfo=  shift;
+sub run_testcase ($$) {
+  my ($tinfo, $server_socket)= @_;
 
   mtr_verbose("Running test:", $tinfo->{name});
 
@@ -3197,7 +3224,12 @@ sub run_testcase ($) {
   {
     my @restart= servers_need_restart($tinfo);
     if ( @restart != 0) {
-      stop_servers($tinfo, @restart );
+      # Remember that we restarted for this test case (count restarts)
+      $tinfo->{'restarted'}= 1;
+      stop_servers(@restart );
+      if ($opt_warnings) {
+        check_warnings_post_shutdown($server_socket);
+      }
     }
 
     if ( started(all_servers()) == 0 )
@@ -3336,7 +3368,18 @@ sub run_testcase ($) {
 	{
 	  if ($check_res == 1) {
 	    # Test case had sideeffects, not fatal error, just continue
-	    stop_all_servers();
+            if ($opt_warnings) {
+              # Checking error logs for warnings, so need to stop server
+              # gracefully so that memory leaks etc. can be properly detected.
+              stop_servers(all_servers());
+              check_warnings_post_shutdown($server_socket);
+              # Even if we got warnings here, we should not fail this
+              # particular test, as the warnings may be caused by an earlier
+              # test.
+            } else {
+              # Not checking warnings, so can do a hard shutdown.
+              stop_all_servers();
+            }
 	    mtr_report("Resuming tests...\n");
 	  }
 	  else {
@@ -3468,6 +3511,41 @@ sub run_testcase ($) {
 }
 
 
+# Keep track of last position in mysqld error log where we scanned for
+# warnings, so we can attribute any warnings found to the correct test
+# suite or server restart.
+my $last_warning_position= { };
+
+# Called just before a mysqld server is started or a testcase is run,
+# to keep track of which tests have been run since last restart, and
+# of when the error log is reset.
+#
+# Second argument $test_name is test name, or undef for server restart.
+sub pre_write_errorlog {
+  my ($error_log, $test_name)= @_;
+
+  if (! -e $error_log) {
+    # If the error log is moved away, reset the warning parse position.
+    delete $last_warning_position->{$error_log};
+  }
+
+  if (defined($test_name)) {
+    $last_warning_position->{$error_log}{test_names}= []
+      unless exists($last_warning_position->{$error_log}{test_names});
+    push @{$last_warning_position->{$error_log}{test_names}}, $test_name;
+  } else {
+    # Server restart, so clear the list of tests run since last restart.
+    # (except the last one (if any), which is the test about to be run).
+    if (defined($last_warning_position->{$error_log}{test_names}) &&
+        @{$last_warning_position->{$error_log}{test_names}}) {
+      $last_warning_position->{$error_log}{test_names}=
+        [$last_warning_position->{$error_log}{test_names}[-1]];
+    } else {
+      $last_warning_position->{$error_log}{test_names}= [];
+    }
+  }
+}
+
 #
 # Perform a rough examination of the servers
 # error log and write all lines that look
@@ -3479,18 +3557,12 @@ sub extract_warning_lines ($) {
   # Open the servers .err log file and read all lines
   # belonging to current tets into @lines
   my $Ferr = IO::File->new($error_log)
-    or mtr_error("Could not open file '$error_log' for reading: $!");
+    or return [];
+  my $last_pos= $last_warning_position->{$error_log}{seek_pos};
+  $Ferr->seek($last_pos, 0) if defined($last_pos);
 
-  my @lines;
-  while ( my $line = <$Ferr> )
-  {
-    if ( $line =~ /^CURRENT_TEST:/ )
-    {
-      # Throw away lines from previous tests
-      @lines = ();
-    }
-    push(@lines, $line);
-  }
+  my @lines= <$Ferr>;
+  $last_warning_position->{$error_log}{seek_pos}= $Ferr->tell();
   $Ferr = undef; # Close error log file
 
   # mysql_client_test.test sends a COM_DEBUG packet to the server
@@ -3537,20 +3609,47 @@ sub extract_warning_lines ($) {
      qr/Attempting backtrace/,
      qr/Assertion .* failed/,
     );
+  # These are taken from the include/mtr_warnings.sql global suppression
+  # list. They occur delayed, so they can be parsed during shutdown rather
+  # than during the per-test check.
+  #
+  # ToDo: having the warning suppressions inside the mysqld we are trying to
+  # check is in any case horrible. We should change it to all be done here
+  # within the Perl code, which is both simpler, easier, faster, and more
+  # robust. We could still have individual test cases put in suppressions by
+  # parsing statically or by writing dynamically to a CSV table read by the
+  # Perl code.
+  my @antipatterns =
+    (
+     qr/InnoDB: Error: in ALTER TABLE `test`.`t[12]`/,
+     qr/InnoDB: Error: table `test`.`t[12]` does not exist in the InnoDB internal/,
+    );
 
-  foreach my $line ( @lines )
+  my $match_count= 0;
+  LINE: foreach my $line ( @lines )
   {
-    foreach my $pat ( @patterns )
+    PAT: foreach my $pat ( @patterns )
     {
       if ( $line =~ /$pat/ )
       {
+        foreach my $apat (@antipatterns)
+        {
+          next LINE if $line =~ $apat;
+        }
 	print $Fwarn $line;
-	last;
+        ++$match_count;
+	last PAT;
       }
     }
   }
   $Fwarn = undef; # Close file
 
+  if ($match_count > 0 &&
+      defined($last_warning_position->{$error_log}{test_names})) {
+    return $last_warning_position->{$error_log}{test_names};
+  } else {
+    return [];
+  }
 }
 
 
@@ -3717,6 +3816,22 @@ sub check_warnings ($) {
   mtr_error("INTERNAL_ERROR: check_warnings");
 }
 
+# Check for warnings generated during shutdown of a mysqld server.
+# If any, report them to master server, and return true; else just return false.
+sub check_warnings_post_shutdown {
+  my ($server_socket)= @_;
+  my $testname_hash= { };
+  foreach my $mysqld ( mysqlds())
+  {
+    my $testlist= extract_warning_lines($mysqld->value('log-error'));
+    $testname_hash->{$_}= 1 for @$testlist;
+  }
+  my @warning_tests= keys(%$testname_hash);
+  if (@warning_tests) {
+    my $fake_test= My::Test->new(testnames => \@warning_tests);
+    $fake_test->write_test($server_socket, 'WARNINGS');
+  }
+}
 
 #
 # Loop through our list of processes and look for and entry
@@ -4142,6 +4257,7 @@ sub mysqld_start ($$) {
 
   if ( defined $exe )
   {
+    pre_write_errorlog($output);
     $mysqld->{'proc'}= My::SafeProcess->new
       (
        name          => $mysqld->name(),
@@ -4371,10 +4487,7 @@ sub get_extra_opts {
 
 
 sub stop_servers($$) {
-  my ($tinfo, @servers)= @_;
-
-  # Remember if we restarted for this test case (count restarts)
-  $tinfo->{'restarted'}= 1;
+  my (@servers)= @_;
 
   if ( join('|', @servers) eq join('|', all_servers()) )
   {