Bug #50407 mysqlbinlog --database=X produces bad output for SAVEPOINTs

When mysqlbinlog was given the --database=X flag, it always printed
'ROLLBACK TO', but the corresponding 'SAVEPOINT' statement was not
printed. The replicated filter(replicated-do/ignore-db) and binlog
filter (binlog-do/ignore-db) has the same problem. They are solved
in this patch together.

After this patch, We always check whether the query is 'SAVEPOINT'
statement or not. Because this is a literal check, 'SAVEPOINT' and
'ROLLBACK TO' statements are also binlogged in uppercase with no
any comments.

The binlog before this patch can be handled correctly except one case
that any comments are in front of the keywords. for example:
 /* bla bla */ SAVEPOINT a;
 /* bla bla */ ROLLBACK TO a;

client/mysqlbinlog.cc

@@ -730,9 +730,7 @@ Exit_status process_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev,
 
     switch (ev_type) {
     case QUERY_EVENT:
-      if (strncmp(((Query_log_event*)ev)->query, "BEGIN", 5) && 
-          strncmp(((Query_log_event*)ev)->query, "COMMIT", 6) && 
-          strncmp(((Query_log_event*)ev)->query, "ROLLBACK", 8) &&  
+      if (!((Query_log_event*)ev)->is_trans_keyword() &&
           shall_skip_database(((Query_log_event*)ev)->db))
         goto end;
       if (opt_base64_output_mode == BASE64_OUTPUT_ALWAYS)

mysql-test/r/mysqlbinlog.result

@@ -479,7 +479,7 @@ FLUSH LOGS;
 RESET MASTER;
 FLUSH LOGS;
 #
-# Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified is exist
+# Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified exists
 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 DELIMITER /*!*/;
@@ -532,7 +532,7 @@ DELIMITER ;
 ROLLBACK /* added by mysqlbinlog */;
 /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 #
-# Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified is not exist
+# Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified does not exist
 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 DELIMITER /*!*/;
@@ -565,5 +565,76 @@ DELIMITER ;
 # End of log file
 ROLLBACK /* added by mysqlbinlog */;
 /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+#
+# Test if the 'SAVEPOINT', 'ROLLBACK TO' are output if the database specified exists
+/*!40019 SET @@session.max_insert_delayed_threads=0*/;
+/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
+DELIMITER /*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+SET @@session.pseudo_thread_id=999999999/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+BEGIN
+/*!*/;
+use test/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+SavePoint mixed_cases
+/*!*/;
+use db1/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+INSERT INTO db1.t2 VALUES("in savepoint mixed_cases")
+/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+INSERT INTO db1.t1 VALUES(40)
+/*!*/;
+use test/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+ROLLBACK TO mixed_cases
+/*!*/;
+use db1/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+INSERT INTO db1.t2 VALUES("after rollback to")
+/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+INSERT INTO db1.t1 VALUES(50)
+/*!*/;
+COMMIT/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+#
+# Test if the 'SAVEPOINT', 'ROLLBACK TO' are output if the database specified does not exist
+/*!40019 SET @@session.max_insert_delayed_threads=0*/;
+/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
+DELIMITER /*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+SET @@session.pseudo_thread_id=999999999/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+BEGIN
+/*!*/;
+use test/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+SavePoint mixed_cases
+/*!*/;
+SET TIMESTAMP=1266652094/*!*/;
+ROLLBACK TO mixed_cases
+/*!*/;
+COMMIT/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 End of 5.0 tests
 End of 5.1 tests

mysql-test/suite/binlog/r/binlog_row_mix_innodb_myisam.result

@@ -48,12 +48,12 @@ Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 master-bin.000001	#	Query	#	#	BEGIN
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; savepoint my_savepoint
+master-bin.000001	#	Query	#	#	SAVEPOINT my_savepoint
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t2)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; rollback to savepoint my_savepoint
+master-bin.000001	#	Query	#	#	ROLLBACK TO my_savepoint
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */
 delete from t1;
 delete from t2;
@@ -77,12 +77,12 @@ Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 master-bin.000001	#	Query	#	#	BEGIN
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; savepoint my_savepoint
+master-bin.000001	#	Query	#	#	SAVEPOINT my_savepoint
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t2)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; rollback to savepoint my_savepoint
+master-bin.000001	#	Query	#	#	ROLLBACK TO my_savepoint
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */

mysql-test/suite/binlog/r/binlog_stm_mix_innodb_myisam.result

@@ -44,10 +44,10 @@ show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 master-bin.000001	#	Query	#	#	BEGIN
 master-bin.000001	#	Query	#	#	use `test`; insert into t1 values(3)
-master-bin.000001	#	Query	#	#	use `test`; savepoint my_savepoint
+master-bin.000001	#	Query	#	#	SAVEPOINT my_savepoint
 master-bin.000001	#	Query	#	#	use `test`; insert into t1 values(4)
 master-bin.000001	#	Query	#	#	use `test`; insert into t2 select * from t1
-master-bin.000001	#	Query	#	#	use `test`; rollback to savepoint my_savepoint
+master-bin.000001	#	Query	#	#	ROLLBACK TO my_savepoint
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */
 delete from t1;
 delete from t2;
@@ -70,10 +70,10 @@ show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 master-bin.000001	#	Query	#	#	BEGIN
 master-bin.000001	#	Query	#	#	use `test`; insert into t1 values(5)
-master-bin.000001	#	Query	#	#	use `test`; savepoint my_savepoint
+master-bin.000001	#	Query	#	#	SAVEPOINT my_savepoint
 master-bin.000001	#	Query	#	#	use `test`; insert into t1 values(6)
 master-bin.000001	#	Query	#	#	use `test`; insert into t2 select * from t1
-master-bin.000001	#	Query	#	#	use `test`; rollback to savepoint my_savepoint
+master-bin.000001	#	Query	#	#	ROLLBACK TO my_savepoint
 master-bin.000001	#	Query	#	#	use `test`; insert into t1 values(7)
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */
 delete from t1;

mysql-test/suite/rpl/r/rpl_begin_commit_rollback.result

@@ -5,7 +5,9 @@ reset slave;
 drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
 start slave;
 DROP DATABASE IF EXISTS db1;
+DROP DATABASE IF EXISTS db2;
 CREATE DATABASE db1;
+CREATE DATABASE db2;
 use db1;
 CREATE TABLE db1.t1 (a INT) ENGINE=InnoDB;
 CREATE TABLE db1.t2 (s CHAR(255)) ENGINE=MyISAM;
@@ -102,8 +104,66 @@ SELECT * from db1.t2;
 s
 before call db1.p1()
 executed db1.p2()
+START SLAVE;
+#
+# SAVEPOINT and ROLLBACK TO have the same problem in BUG#43263
+# This was reported by BUG#50407
+[on master]
+SET SESSION AUTOCOMMIT=0
+BEGIN;
+INSERT INTO db1.t1 VALUES(20);
+# 
+# Verify whether this statement is binlogged correctly
+/*comment*/ SAVEPOINT has_comment;
+USE db1;
+INSERT INTO db1.t1 VALUES(30);
+INSERT INTO db1.t2 VALUES("in savepoint has_comment");
+USE db2;
+SavePoint mixed_cases;
+USE db1;
+INSERT INTO db1.t2 VALUES("in savepoint mixed_cases");
+INSERT INTO db1.t1 VALUES(40);
+USE db2;
+ROLLBACK TO mixed_cases;
+Warnings:
+Warning	1196	Some non-transactional changed tables couldn't be rolled back
+ROLLBACK TO has_comment;
+Warnings:
+Warning	1196	Some non-transactional changed tables couldn't be rolled back
+USE db1;
+INSERT INTO db1.t2 VALUES("after rollback to");
+INSERT INTO db1.t1 VALUES(50);
+USE db2;
+COMMIT;
+show binlog events from <binlog_start>;
+Log_name	Pos	Event_type	Server_id	End_log_pos	Info
+master-bin.000001	#	Query	#	#	BEGIN
+master-bin.000001	#	Query	#	#	use `test`; INSERT INTO db1.t1 VALUES(20)
+master-bin.000001	#	Query	#	#	SAVEPOINT has_comment
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t1 VALUES(30)
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t2 VALUES("in savepoint has_comment")
+master-bin.000001	#	Query	#	#	SAVEPOINT mixed_cases
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t2 VALUES("in savepoint mixed_cases")
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t1 VALUES(40)
+master-bin.000001	#	Query	#	#	ROLLBACK TO mixed_cases
+master-bin.000001	#	Query	#	#	ROLLBACK TO has_comment
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t2 VALUES("after rollback to")
+master-bin.000001	#	Query	#	#	use `db1`; INSERT INTO db1.t1 VALUES(50)
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
+[on slave]
+#
+# Verify INSERT statements in savepoints are executed, for MyISAM table
+# is not effected by ROLLBACK TO
+SELECT * FROM db1.t2 WHERE s LIKE '% savepoint %';
+s
+in savepoint has_comment
+in savepoint mixed_cases
+#
+# Verify INSERT statements on the Innodb table are rolled back;
+SELECT * FROM db1.t1 WHERE a IN (30, 40);
+a
 #
 # Clean up
 #
 DROP DATABASE db1;
-DROP DATABASE db1;
+DROP DATABASE db2;

mysql-test/suite/rpl/r/rpl_innodb_mixed_dml.result

@@ -998,7 +998,7 @@ master-bin.000001	#	Query	1	#	use `test_rpl`; INSERT INTO t1 VALUES (3, 'before
 master-bin.000001	#	Xid	1	#	#
 master-bin.000001	#	Query	1	#	BEGIN
 master-bin.000001	#	Query	1	#	use `test_rpl`; INSERT INTO t1 VALUES (5, 'before savepoint s2')
-master-bin.000001	#	Query	1	#	use `test_rpl`; SAVEPOINT s2
+master-bin.000001	#	Query	1	#	SAVEPOINT s2
 master-bin.000001	#	Query	1	#	use `test_rpl`; INSERT INTO t1 VALUES (6, 'after savepoint s2')
 master-bin.000001	#	Table_map	1	#	table_id: # (test_rpl.t1)
 master-bin.000001	#	Write_rows	1	#	table_id: # flags: STMT_END_F

mysql-test/suite/rpl/t/rpl_begin_commit_rollback-master.opt

+--innodb --binlog-ignore-db=db2

mysql-test/suite/rpl/t/rpl_begin_commit_rollback.test

@@ -4,9 +4,11 @@ source include/have_binlog_format_statement.inc;
 
 disable_warnings;
 DROP DATABASE IF EXISTS db1;
+DROP DATABASE IF EXISTS db2;
 enable_warnings;
 
 CREATE DATABASE db1;
+CREATE DATABASE db2;
 
 use db1;
 
@@ -116,10 +118,55 @@ eval SELECT $result as 'Must be 0';
 SELECT * from db1.t1;
 SELECT * from db1.t2;
 
+START SLAVE;
+source include/wait_for_slave_sql_to_start.inc;
+
+--echo #
+--echo # SAVEPOINT and ROLLBACK TO have the same problem in BUG#43263
+--echo # This was reported by BUG#50407
+connection master;
+echo [on master]
+SET SESSION AUTOCOMMIT=0;
+let $binlog_start=query_get_value(SHOW MASTER STATUS, Position, 1);
+
+BEGIN;
+INSERT INTO db1.t1 VALUES(20);
+
+--echo # 
+--echo # Verify whether this statement is binlogged correctly
+/*comment*/ SAVEPOINT has_comment;
+USE db1;
+INSERT INTO db1.t1 VALUES(30);
+INSERT INTO db1.t2 VALUES("in savepoint has_comment");
+USE db2;
+SavePoint mixed_cases;
+USE db1;
+INSERT INTO db1.t2 VALUES("in savepoint mixed_cases");
+INSERT INTO db1.t1 VALUES(40);
+USE db2;
+ROLLBACK TO mixed_cases;
+ROLLBACK TO has_comment;
+USE db1;
+INSERT INTO db1.t2 VALUES("after rollback to");
+INSERT INTO db1.t1 VALUES(50);
+USE db2;
+COMMIT;
+source include/show_binlog_events.inc;
+sync_slave_with_master;
+
+--echo [on slave]
+--echo #
+--echo # Verify INSERT statements in savepoints are executed, for MyISAM table
+--echo # is not effected by ROLLBACK TO
+SELECT * FROM db1.t2 WHERE s LIKE '% savepoint %';
+--echo #
+--echo # Verify INSERT statements on the Innodb table are rolled back;
+SELECT * FROM db1.t1 WHERE a IN (30, 40);
+
 --echo #
 --echo # Clean up
 --echo #
 connection master;
 DROP DATABASE db1;
-connection slave;
-DROP DATABASE db1;
+DROP DATABASE db2;
+source include/master-slave-end.inc;

mysql-test/t/mysqlbinlog.test

@@ -434,12 +434,19 @@ FLUSH LOGS;
 # Transaction3 end
 
 --echo #
---echo # Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified is exist
+--echo # Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified exists
 --exec $MYSQL_BINLOG --database=test --short-form $MYSQLTEST_VARDIR/std_data/binlog_transaction.000001
 --echo #
---echo # Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified is not exist
+--echo # Test if the 'BEGIN', 'ROLLBACK' and 'COMMIT' are output if the database specified does not exist
 --exec $MYSQL_BINLOG --database=not_exist --short-form $MYSQLTEST_VARDIR/std_data/binlog_transaction.000001
 
+--echo #
+--echo # Test if the 'SAVEPOINT', 'ROLLBACK TO' are output if the database specified exists
+--exec $MYSQL_BINLOG --database=db1 --short-form $MYSQLTEST_VARDIR/std_data/binlog_savepoint.000001
+--echo #
+--echo # Test if the 'SAVEPOINT', 'ROLLBACK TO' are output if the database specified does not exist
+--exec $MYSQL_BINLOG --database=not_exist --short-form $MYSQLTEST_VARDIR/std_data/binlog_savepoint.000001
+
 --echo End of 5.0 tests
 
 --echo End of 5.1 tests

sql/log.cc

@@ -1714,11 +1714,14 @@ static int binlog_savepoint_set(handlerton *hton, THD *thd, void *sv)
   binlog_trans_log_savepos(thd, (my_off_t*) sv);
   /* Write it to the binary log */
 
+  String log_query;
+  if (log_query.append(STRING_WITH_LEN("SAVEPOINT ")) ||
+      log_query.append(thd->lex->ident.str, thd->lex->ident.length))
+    DBUG_RETURN(1);
   int errcode= query_error_code(thd, thd->killed == THD::NOT_KILLED);
-  int const error=
-    thd->binlog_query(THD::STMT_QUERY_TYPE,
-                      thd->query(), thd->query_length(), TRUE, FALSE, errcode);
-  DBUG_RETURN(error);
+  Query_log_event qinfo(thd, log_query.c_ptr_safe(), log_query.length(),
+                        TRUE, TRUE, errcode);
+  DBUG_RETURN(mysql_bin_log.write(&qinfo));
 }
 
 static int binlog_savepoint_rollback(handlerton *hton, THD *thd, void *sv)
@@ -1733,11 +1736,14 @@ static int binlog_savepoint_rollback(handlerton *hton, THD *thd, void *sv)
   if (unlikely(thd->transaction.all.modified_non_trans_table || 
                (thd->options & OPTION_KEEP_LOG)))
   {
+    String log_query;
+    if (log_query.append(STRING_WITH_LEN("ROLLBACK TO ")) ||
+        log_query.append(thd->lex->ident.str, thd->lex->ident.length))
+      DBUG_RETURN(1);
     int errcode= query_error_code(thd, thd->killed == THD::NOT_KILLED);
-    int error=
-      thd->binlog_query(THD::STMT_QUERY_TYPE,
-                        thd->query(), thd->query_length(), TRUE, FALSE, errcode);
-    DBUG_RETURN(error);
+    Query_log_event qinfo(thd, log_query.c_ptr_safe(), log_query.length(),
+                          TRUE, TRUE, errcode);
+    DBUG_RETURN(mysql_bin_log.write(&qinfo));
   }
   binlog_trans_log_truncate(thd, *(my_off_t*)sv);
   DBUG_RETURN(0);
@@ -4272,7 +4278,9 @@ bool MYSQL_BIN_LOG::write(Log_event *event_info)
     */
     const char *local_db= event_info->get_db();
     if ((thd && !(thd->options & OPTION_BIN_LOG)) ||
-	(!binlog_filter->db_ok(local_db)))
+	(thd->lex->sql_command != SQLCOM_ROLLBACK_TO_SAVEPOINT &&
+         thd->lex->sql_command != SQLCOM_SAVEPOINT &&
+         !binlog_filter->db_ok(local_db)))
     {
       VOID(pthread_mutex_unlock(&LOCK_log));
       DBUG_RETURN(0);

sql/log_event.cc

@@ -3063,10 +3063,7 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli,
             ::do_apply_event(), then the companion SET also have so
             we don't need to reset_one_shot_variables().
   */
-  if (!strncmp(query_arg, "BEGIN", q_len_arg) ||
-      !strncmp(query_arg, "COMMIT", q_len_arg) ||
-      !strncmp(query_arg, "ROLLBACK", q_len_arg) ||
-      rpl_filter->db_ok(thd->db))
+  if (is_trans_keyword() || rpl_filter->db_ok(thd->db))
   {
     thd->set_time((time_t)when);
     thd->set_query((char*)query_arg, q_len_arg);

sql/log_event.h

@@ -1682,6 +1682,28 @@ class Query_log_event: public Log_event
                        const char *query_arg,
                        uint32 q_len_arg);
 #endif /* HAVE_REPLICATION */
+  /*
+    If true, the event always be applied by slave SQL thread or be printed by
+    mysqlbinlog
+   */
+  bool is_trans_keyword()
+  {
+    /*
+      Before the patch for bug#50407, The 'SAVEPOINT and ROLLBACK TO'
+      queries input by user was written into log events directly.
+      So the keywords can be written in both upper case and lower case
+      together, strncasecmp is used to check both cases. they also could be
+      binlogged with comments in the front of these keywords. for examples:
+        / * bla bla * / SAVEPOINT a;
+        / * bla bla * / ROLLBACK TO a;
+      but we don't handle these cases and after the patch, both quiries are
+      binlogged in upper case with no comments.
+     */
+    return !strncmp(query, "BEGIN", q_len) ||
+      !strncmp(query, "COMMIT", q_len) ||
+      !strncasecmp(query, "SAVEPOINT", 9) ||
+      !strncasecmp(query, "ROLLBACK", 8);
+  }
 };