BUG#17650326 MYSQLBINLOG PRINTS INVALID SQL FROM RELAY LOGS WHEN GTID IS ENABLED

Venkatesh Duggirala · Venkatesh Duggirala · commit 44a901a0d5fb · 2015-04-16T11:40:48.000+05:30
Problem (1) : Replaying a relaylog which ends with GTID_LOG_EVENT causes
error "ERROR 1790 (HY000) @@SESSION.GTID_NEXT cannot be changed by a client
that owns a GTID. The client owns &lt;UUID:GTID&gt; Ownership is released on
COMMIT or ROLLBACK."

Analysis: mysqlbinlog tool appends SET @@SESSION.GTID_NEXT='AUTOMATIC'
to output when it finds a rotate log event and if it is not inside
a transaction which is the right thing to do. The tool has in_transaction
flag which will be set true upon processing any transaction event.
But a GTID_LOG_EVENT is not treated as a transaction event,
hence in_transaction is false even after processing GTID_LOG_EVENT.
If a relaylog rotate happens (either through IO thread restart/ROTATE
command), exactly after writing GTID_LOG_EVENT and if we are replaying such a
relaylog's end ROTATE_EVENT, logic was mistakenly thinking that it was not
inside a transaction but actually the transaction was started after
GTID_LOG_EVENT. Hence tool generates SET @@SESSION.GTID_NEXT='AUTOMATIC'.
This issue resulted in having two GTID_NEXT statements next to each other and
replaying such output against 'mysql' client tool was causing above specified
error (ERROR:1790).

Fix: One way to fix this issue is to set in_transaction flag to true when it
encounters GTID_LOG_EVENT. But this change will disturb DDL transaction
detection logic (mysqlbinlog tool logic assumes that DDL transactions will
have only one event per transaction). So instead of disturbing that logic,
we have followed another approach to solve the issue. 'mysqlbinlog' tool
generates "SET @@SESSION.GTID_NEXT='AUTOMATIC'" only when in_transaction
is false and is_gtid_next_valid is false (which represents that we are
not in transaction and did not even see GTID_LOG_EVENT.

Problem (2): 'ROLLBACK' is not getting generated by mysqlbinlog tool
when concatenating and replaying two consecutive relaylogs
(the first relaylog contains partial transaction and second relaylog
contains full transaction again).

Analysis: If IO thread is restarted when it is in the middle of
transferring a tranasction from Master then it will retrieve the
full transaction again upon restart. In that case, the first relaylog
contains partial GTID transaction and the second relaylog will
contain full GTID transaction again. If mysqlbinlog tool is used
to merge such two relaylogs it should generate a 'ROLLBACK' statement
after partial transaction. Otherwise it will cause above said error
(ERROR:1790).

Fix: If IO thread is restarted, the new generated relaylog will have
FD event received from Master and will have log_pos greater than zero
if the AUTO_POSITION is true i.e., this will indicate that if we
were in transaction in first relaylog, Master would have sent the
transaction again from the beginning. In this case, upon reading such
a FD event, generate 'ROLLBACK' statement in generated output. If
we have seen only GTID_LOG_EVENT of the transaction and not seen
'BEGIN' statement, then generate BEGIN and ROLLBACK statements
in generated output.
diff --git a/client/mysqlbinlog.cc b/client/mysqlbinlog.cc
@@ -1087,9 +1087,66 @@ Exit_status process_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev,
     case FORMAT_DESCRIPTION_EVENT:
       delete glob_description_event;
       glob_description_event= (Format_description_log_event*) ev;
+      /*
+        The first FD event in log is always generated
+        from the local server. So if it is first FD event to be
+        processed (i.e., if server_id_from_fd_event is 0),
+        get server_id from the FD event and keep it in
+        server_id_from_fd_event to differentiate between FDs
+        (originated from local server vs another server).
+       */
+      if (print_event_info->server_id_from_fd_event == 0)
+        print_event_info->server_id_from_fd_event= ev->server_id;
+
       print_event_info->common_header_len=
         glob_description_event->common_header_len;
       ev->print(result_file, print_event_info);
+      /*
+        At this point, if we are in transaction that means
+        we are reading a relay log file (transaction cannot
+        spawn across two binary log files, they are writen
+        at once in binlog). When AUTO_POSITION is enabled
+        and if IO thread stopped in between the GTID transaction,
+        upon IO thread restart, Master will send the GTID events
+        again from the begin of the transaction. Hence, we should
+        rollback the old transaction.
+
+        If you are reading FD event that came from Master
+        (first FD event is from the server that owns the relaylog
+        and second one is from Master) and if it's log_pos is > 0
+        then it represents the begin of a master's binary log
+        (any unfinished transaction will not be finished) or that
+        auto_position is enabled (any partial transaction left will
+        not be finished but will be fully retrieved again). On both
+        cases, the next transaction in the relay log will start from the
+        beginning and we must rollback any unfinished transaction
+      */
+      if (ev->server_id !=0 &&
+          ev->server_id != print_event_info->server_id_from_fd_event &&
+          ev->log_pos > 0)
+      {
+        if (in_transaction)
+        {
+          my_b_printf(&print_event_info->head_cache,
+                      "ROLLBACK /* added by mysqlbinlog */ %s\n",
+                      print_event_info->delimiter);
+        }
+        else if (print_event_info->is_gtid_next_set &&
+                 print_event_info->is_gtid_next_valid)
+        {
+          /*
+            If we are here, then we have seen only GTID_LOG_EVENT
+            of a transaction and did not see even a BEGIN event
+            (in_transaction flag is false). So generate BEGIN event
+            also along with ROLLBACK event.
+          */
+          my_b_printf(&print_event_info->head_cache,
+                      "BEGIN /*added by mysqlbinlog */ %s\n"
+                      "ROLLBACK /* added by mysqlbinlog */ %s\n",
+                      print_event_info->delimiter,
+                      print_event_info->delimiter);
+        }
+      }
       if (head->error == -1)
         goto err;
       if (opt_remote_proto == BINLOG_LOCAL)
@@ -1331,7 +1388,21 @@ Exit_status process_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev,
           Fake rotate events have 'when' set to zero. @c fake_rotate_event(...).
         */
         bool is_fake= (rev->when.tv_sec == 0);
-        if (!in_transaction && !is_fake)
+        /*
+          'in_transaction' flag is not set to true even after GTID_LOG_EVENT
+          of a transaction is seen. ('mysqlbinlog' tool assumes that there
+          is only one event per DDL transaction other than BEGIN and COMMIT
+          events. Using 'in_transaction' flag and 'starts_group', 'ends_group'
+          flags, DDL transaction generation is handled. Hence 'in_transaction'
+          cannot be set to true after seeing GTID_LOG_EVENT). So in order to
+          see if we are out of a transaction or not, we should check that
+          'in_transaction' is false and we have not seen GTID_LOG_EVENT.
+          To see if a GTID_LOG_EVENT of a transaction is seen or not,
+          we should check is_gtid_next_valid flag is false.
+        */
+        if (!is_fake && !in_transaction &&
+            print_event_info->is_gtid_next_set &&
+            !print_event_info->is_gtid_next_valid)
         {
           /*
             If processing multiple files, we must reset this flag,
diff --git a/mysql-test/suite/rpl/r/rpl_gtid_replay_relaylog.result b/mysql-test/suite/rpl/r/rpl_gtid_replay_relaylog.result
@@ -0,0 +1,28 @@
+include/master-slave.inc
+Warnings:
+Note	####	Sending passwords in plain text without SSL/TLS is extremely insecure.
+Note	####	Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
+[connection master]
+CREATE TABLE t1(i INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUES (1);
+include/sync_slave_sql_with_master.inc
+SET @save_debug=@@global.debug;
+SET GLOBAL DEBUG='d,stop_io_after_reading_gtid_log_event';
+[connection master]
+INSERT INTO t1 VALUES (2);
+[connection slave]
+include/wait_for_slave_io_to_stop.inc
+include/assert.inc [Slave MASTER_AUTO_POSITION should be enabled for this test]
+SET GLOBAL DEBUG= @save_debug;
+include/start_slave.inc
+[connection master]
+include/sync_slave_sql_with_master.inc
+DROP TABLE t1;
+RESET MASTER;
+include/assert.inc [Check that there is one tuple in the table]
+DROP TABLE t1;
+RESET MASTER;
+include/assert.inc [Check that there are two tuples in the table]
+[connection master]
+DROP TABLE t1;
+include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_gtid_replay_relaylog.test b/mysql-test/suite/rpl/t/rpl_gtid_replay_relaylog.test
@@ -0,0 +1,81 @@
+############################################################################
+# Bug #17650326  MYSQLBINLOG PRINTS INVALID SQL FROM RELAY LOGS WHEN GTID IS
+# ENABLED
+# Problem: Replaying a relaylog which ends with GTID_LOG_EVENT causes error
+# "ERROR 1790 (HY000) @@SESSION.GTID_NEXT cannot be changed by a client that
+# owns a GTID. The client owns <UUID:GNO>. Ownership is released on COMMIT
+# or ROLLBACK."
+#
+# Steps to reproduce:
+#  1) Stop IO thread after reading gtid_log_event (relaylog 1 contains
+#      GTID_LOG_EVENT at the end)
+#  2) Restart IO thread which rotates relaylog file (relaylog 2)
+#  3) Replay relaylog1's 'mysqlbinlog' output against 'mysql' client tool,
+#     it should not cause any problems.
+#  4) Replay (relaylog1 + relaylog2)'s 'mysqlbinlog' output against
+#     'mysql' client tool, it should not cause any problems.
+#
+############################################################################
+--source include/have_debug.inc
+# This test is not need against MTS setup
+--source include/not_mts_slave_parallel_workers.inc
+--source include/have_gtid.inc
+--source include/have_binlog_format_statement.inc
+--source include/master-slave.inc
+
+# Initial setup
+CREATE TABLE t1(i INT) ENGINE=InnoDB;
+INSERT INTO t1 VALUES (1);
+--source include/sync_slave_sql_with_master.inc
+--let MYSQLD_DATADIR=`select @@datadir`
+SET @save_debug=@@global.debug;
+
+# Step 1: Stop I/O thread after reading GTID_LOG_EVENT
+# This will leave the relaylog in incomplete state(i.e., it ends
+# with GTID_LOG_EVENT)
+SET GLOBAL DEBUG='d,stop_io_after_reading_gtid_log_event';
+
+--source include/rpl_connection_master.inc
+INSERT INTO t1 VALUES (2);
+
+--source include/rpl_connection_slave.inc
+--source include/wait_for_slave_io_to_stop.inc
+--let $relay_file1 = query_get_value( SHOW SLAVE STATUS, Relay_Log_File, 1 )
+
+--let $auto_pos = query_get_value( SHOW SLAVE STATUS, Auto_Position, 1 )
+--let $assert_text= Slave MASTER_AUTO_POSITION should be enabled for this test
+--let $assert_cond= $auto_pos= 1
+--source include/assert.inc
+
+# Step 2: Restart I/O thread and execute the pending INSERT(2)
+SET GLOBAL DEBUG= @save_debug;
+--source include/start_slave.inc
+
+--source include/rpl_connection_master.inc
+--source include/sync_slave_sql_with_master.inc
+--let $relay_file2 = query_get_value( SHOW SLAVE STATUS, Relay_Log_File, 1 )
+
+# Step 3: Replay the incomplete Relaylog's mysqlbinlog output against mysql and see that
+# there are no issues.
+DROP TABLE t1;
+RESET MASTER;
+--exec $MYSQL_BINLOG --force-if-open $MYSQLD_DATADIR/$relay_file1 | $MYSQL -uroot -S$SLAVE_MYSOCK
+
+--let $assert_text= Check that there is one tuple in the table
+--let $assert_cond= [SELECT COUNT(*) AS Val FROM t1 where i=1, Val, 1] = 1
+--source include/assert.inc
+
+# Step 4: Concat two relay logs and then replay mysqlbinlog ouput against mysql and see
+# that there are no issues.
+DROP TABLE t1;
+RESET MASTER;
+--exec $MYSQL_BINLOG --force-if-open $MYSQLD_DATADIR/$relay_file1 $MYSQLD_DATADIR/$relay_file2 | $MYSQL -uroot -S$SLAVE_MYSOCK
+
+--let $assert_text= Check that there are two tuples in the table
+--let $assert_cond= [SELECT COUNT(*) AS Val FROM t1 where i=1 or i=2, Val, 1] = 2
+--source include/assert.inc
+
+# Cleanup
+--source include/rpl_connection_master.inc
+DROP TABLE t1;
+--source include/rpl_end.inc
diff --git a/sql/log_event.cc b/sql/log_event.cc
@@ -13781,7 +13781,7 @@ st_print_event_info::st_print_event_info()
    auto_increment_increment(0),auto_increment_offset(0), charset_inited(0),
    lc_time_names_number(~0),
    charset_database_number(ILLEGAL_CHARSET_INFO_NUMBER),
-   thread_id(0), thread_id_printed(false),
+   thread_id(0), thread_id_printed(false),server_id_from_fd_event(0),
    base64_output_mode(BASE64_OUTPUT_UNSPEC), printed_fd_event(FALSE),
    have_unflushed_events(false), skipped_event_in_transaction(false),
    is_gtid_next_set(false), is_gtid_next_valid(true)
diff --git a/sql/log_event.h b/sql/log_event.h
@@ -1,4 +1,4 @@
-/* Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.
+/* Copyright (c) 2000, 2015, 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 as published by
@@ -788,6 +788,7 @@ typedef struct st_print_event_info
   uint charset_database_number;
   uint thread_id;
   bool thread_id_printed;
+  uint32 server_id_from_fd_event;
 
   st_print_event_info();
 
