BUG#50620: Adding an index to a table prevents slave from logging

into slow log
      
While processing a statement, down the mysql_parse execution
stack, the thd->enable_slow_log can be assigned to
opt_log_slow_admin_statements, depending whether one is executing
administrative statements, such as ALTER TABLE, OPTIMIZE,
ANALYZE, etc, or not. This can have an impact on slow logging for
statements that are executed after an administrative statement
execution is completed.
      
When executing statements directly from the user this is fine
because, the thd->enable_slow_log is reset right at the beginning
of the dispatch_command function, ie, everytime a new statement
is set is set to execute.
      
On the other hand, for slave SQL thread (sql_thd) the story is a
bit different. When in SBR the sql_thd applies statements by
calling mysql_parse. Right after, it calls log_slow_statement
function to log them if they take too long. Calling mysql_parse
directly is fine, but also means that dispatch_command function
is bypassed. As a consequence, thd->enable_slow_log does not get
a chance to be reset before the next statement to be executed by
the sql_thd. If the statement just executed by the sql_thd was an
administrative statement and logging of admin statements was
disabled, this means that sql_thd->enable_slow_log will be set to
0 (disabled) from that moment on. End result: sql_thd stops
logging slow statements.
      
We fix this by resetting the value of sql_thd->enable_slow_log to
the value of opt_log_slow_slave_statements right after
log_slow_stement is called by the sql_thd.

2 files changed, 159 insertions, 1 deletions

diff --git a/mysql-test/suite/rpl/r/rpl_slow_query_log.result b/mysql-test/suite/rpl/r/rpl_slow_query_log.result
index fd6a2c5d7c4..a4479f0c544 100644
--- a/mysql-test/suite/rpl/r/rpl_slow_query_log.result
+++ b/mysql-test/suite/rpl/r/rpl_slow_query_log.result
@@ -46,3 +46,46 @@ include/stop_slave.inc
 SET GLOBAL long_query_time= @old_long_query_time;
 SET GLOBAL log_output= @old_log_output;
 include/start_slave.inc
+stop slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+reset master;
+reset slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+start slave;
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET GLOBAL long_query_time= 2;
+SET @old_long_query_time= @@long_query_time;
+SET SESSION long_query_time= 2;
+TRUNCATE mysql.slow_log;
+include/stop_slave.inc
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET @old_long_query_time= @@long_query_time;
+SET GLOBAL long_query_time= 2;
+TRUNCATE mysql.slow_log;
+include/start_slave.inc
+CREATE TABLE t1 (a int, b int);
+********************************************************************
+**** INSERT one row that exceeds long_query_time
+**** Outcome: query ends up in both master and slave slow log
+********************************************************************
+INSERT INTO t1 values(1, sleep(3));
+### Assertion is good. Both Master and Slave exhibit the 
+### same number of queries in slow log: 1
+TRUNCATE mysql.slow_log;
+TRUNCATE mysql.slow_log;
+********************************************************************
+**** Now do inserts again, but first add an index to the table.
+**** Outcome: Note that the slave contains the same one entry (as 
+****          the master does)  whereas before the patch it did not.
+********************************************************************
+ALTER TABLE t1 ADD INDEX id1(a);
+INSERT INTO t1 values(1, sleep(3));
+### Assertion is good. Both Master and Slave exhibit the 
+### same number of queries in slow log: 1
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;
+DROP TABLE t1;
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;
diff --git a/mysql-test/suite/rpl/t/rpl_slow_query_log.test b/mysql-test/suite/rpl/t/rpl_slow_query_log.test
index c310d6a8a4f..ced4859ebe7 100644
--- a/mysql-test/suite/rpl/t/rpl_slow_query_log.test
+++ b/mysql-test/suite/rpl/t/rpl_slow_query_log.test
@@ -175,7 +175,6 @@ TRUNCATE mysql.slow_log;
 # clean up: drop tables, reset the variables back to the previous value,
 #           disconnect extra connections
 connection extra2;
-
 SET GLOBAL slow_query_log= @old_slow_query_log;
 
 connection master;
@@ -191,3 +190,119 @@ source include/start_slave.inc;
 
 disconnect extra;
 disconnect extra2;
+
+#
+# BUG#50620: Adding an index to a table prevents slave from logging into slow log
+#
+
+-- source include/master-slave-reset.inc
+
+-- connection master
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET GLOBAL long_query_time= 2;
+SET @old_long_query_time= @@long_query_time;
+SET SESSION long_query_time= 2;
+TRUNCATE mysql.slow_log;
+-- connection slave
+
+-- source include/stop_slave.inc
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET @old_long_query_time= @@long_query_time;
+SET GLOBAL long_query_time= 2;
+TRUNCATE mysql.slow_log;
+-- source include/start_slave.inc
+
+let $slow_query= INSERT INTO t1 values(1, sleep(3));
+
+-- connection master
+CREATE TABLE t1 (a int, b int); 
+
+-- echo ********************************************************************
+-- echo **** INSERT one row that exceeds long_query_time
+-- echo **** Outcome: query ends up in both master and slave slow log
+-- echo ********************************************************************
+
+-- disable_warnings
+-- eval $slow_query
+-- enable_warnings
+
+let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+-- sync_slave_with_master
+let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if (`SELECT $master_slow_query != $slave_slow_query`)
+{
+  -- connection master
+  -- echo ***********************************************
+  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- connection slave
+  -- echo ***********************************************
+  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
+}
+
+if (`SELECT $master_slow_query = $slave_slow_query`)
+{
+  -- echo ### Assertion is good. Both Master and Slave exhibit the 
+  -- echo ### same number of queries in slow log: $master_slow_query
+}
+
+TRUNCATE mysql.slow_log;
+-- connection master
+TRUNCATE mysql.slow_log;
+
+-- echo ********************************************************************
+-- echo **** Now do inserts again, but first add an index to the table.
+-- echo **** Outcome: Note that the slave contains the same one entry (as 
+-- echo ****          the master does)  whereas before the patch it did not.
+-- echo ********************************************************************
+
+ALTER TABLE t1 ADD INDEX id1(a);
+
+-- disable_warnings
+-- eval $slow_query
+-- enable_warnings
+
+let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+-- sync_slave_with_master
+let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if (`SELECT $master_slow_query != $slave_slow_query`)
+{
+  -- connection master
+  -- echo ***********************************************
+  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- connection slave
+  -- echo ***********************************************
+  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
+}
+
+if (`SELECT $master_slow_query = $slave_slow_query`)
+{
+  -- echo ### Assertion is good. Both Master and Slave exhibit the 
+  -- echo ### same number of queries in slow log: $master_slow_query
+}
+
+-- connection master
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;
+DROP TABLE t1;
+
+-- sync_slave_with_master
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;