Skip to content

Commit

Permalink
Bug#30909369: MTR DOES NOT NOTICE A SERVER ABORT AFTER "BYE"
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
Deepa Dixit committed May 13, 2020
1 parent 5a0b4ba commit 8aeda36
Show file tree
Hide file tree
Showing 3 changed files with 121 additions and 19 deletions.
10 changes: 7 additions & 3 deletions mysql-test/lib/My/SafeProcess.pm
View file
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
# -*- cperl -*-
# Copyright (c) 2007, 2015 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,
Expand Down Expand Up @@ -233,6 +233,7 @@ sub shutdown {
my $shutdown_timeout= shift;
my @processes= @_;
_verbose("shutdown, timeout: $shutdown_timeout, @processes");
my $shutdown_status = 0;

return if (@processes == 0);

Expand All @@ -259,6 +260,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;
Expand All @@ -277,7 +281,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();
Expand All @@ -287,7 +291,7 @@ sub shutdown {
$proc->wait_one(undef);
}

return;
return $shutdown_status;
}


Expand Down
129 changes: 113 additions & 16 deletions mysql-test/mysql-test-run.pl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -322,6 +322,7 @@ END

our $opt_sanitize= 0;
our $opt_valgrind= 0;
my $shutdown_report = 0;
my $opt_valgrind_mysqld= 0;
my $opt_valgrind_clients= 0;
my $opt_valgrind_mysqltest= 0;
Expand Down Expand Up @@ -464,6 +465,10 @@ sub main {
$opt_parallel= 1;
}

# Shutdown report is one extra test created to report
# any failures or crashes during shutdown.
$num_tests_for_report = $num_tests_for_report + 1;

# When either --valgrind or --sanitize option is enabled, a dummy
# test is created.
if ($opt_valgrind_mysqld or $opt_sanitize) {
Expand Down Expand Up @@ -598,6 +603,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_mysqld or $opt_sanitize) {
# Create minimalistic "test" for the reporting
my $tinfo = My::Test->new(
Expand Down Expand Up @@ -842,8 +867,10 @@ ($$$)
# server logs. This will cause the master to flag the pseudo test
# valgrind_report as failed.
$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");
}

Expand Down Expand Up @@ -1023,7 +1050,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 or $opt_sanitize) {
Expand All @@ -1047,6 +1079,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)= @_;
Expand Down Expand Up @@ -4811,7 +4897,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"))
Expand Down Expand Up @@ -5670,7 +5760,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';
Expand Down Expand Up @@ -5991,8 +6082,8 @@ ($$)

my $output= $mysqld->value('#log-error');

# Remember this log file for valgrind error report search
$mysqld_logs{$output}= 1 if $opt_valgrind or $opt_sanitize;
# 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;
Expand Down Expand Up @@ -6040,7 +6131,7 @@ ()
mtr_verbose("Stopping all servers...");

# Kill all started servers
My::SafeProcess::shutdown($shutdown_timeout,
my $ret = My::SafeProcess::shutdown($shutdown_timeout,
started(all_servers()));

# Remove pidfiles
Expand All @@ -6051,8 +6142,8 @@ ()
}

# Mark servers as stopped
map($_->{proc}= undef, all_servers());

map($_->{proc} = undef, all_servers());
return $ret;
}


Expand Down Expand Up @@ -6305,17 +6396,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,
Expand All @@ -6325,11 +6417,16 @@ ($$)
{
mtr_report("Restarting ", started(@servers));

# Stop only some servers
My::SafeProcess::shutdown( $opt_shutdown_timeout,
# 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)
{
# Mark server as stopped
Expand Down
1 change: 1 addition & 0 deletions mysql-test/t/disabled.def
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,3 +17,4 @@ mysql_client_test_embedded : Bug#16084066 2013-01-08 Disabled since this test is
ssl-big : Bug #18977126 MAIN.SSL-BIG FAILS WITH TIMEOUT Times out on weekly, disable it
explain_for_connection_rqg_json : Bug#20697533 2015-03-20 erlend Fails several times each day on all platforms
explain_for_connection_rqg_trad : Bug#20697533 2015-03-20 erlend Fails several times each day on all platforms
daemonize_opt : Bug#31335773 2020-05-12 Deepa Shutdown_report fails

0 comments on commit 8aeda36

Please sign in to comment.