MySQL Bugs: #88358: Break replication by running some XA ROLLBACK statements

Bug #88358	Break replication by running some XA ROLLBACK statements
Submitted:	4 Nov 2017 2:32	Modified:	7 Nov 2017 8:55
Reporter:	Kenny Gryp	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.7.19, 5.7.20	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
Replication breaks when running the wrong XA ROLLBACK statement after preparing it.

The impact here is that you can basically break any replication as any user with just a few SQL statements

How to repeat:

mysql> create table t1 (t1_pk int primary key, t1_blob blob null);
Query OK, 0 rows affected (0.00 sec)

mysql>  xa start '2'; 
Query OK, 0 rows affected (0.00 sec)

mysql> INSERT INTO t1 VALUES (85000, null);
Query OK, 1 row affected (0.00 sec)

mysql> xa end '2';
Query OK, 0 rows affected (0.00 sec)

mysql> xa prepare '2';
Query OK, 0 rows affected (0.00 sec)

mysql> xa rollback '1';
ERROR 1399 (XAE07): XAER_RMFAIL: The command cannot be executed when global transaction is in the  PREPARED state

mysql> xa rollback '2';
Query OK, 0 rows affected (0.00 sec)

On the replica, you will get:

               Last_SQL_Error: Error 'XAER_NOTA: Unknown XID' on query. Default database: 'xa'. Query: 'XA ROLLBACK X'32',X'',1'

The binary log contains:

#171104  2:24:32 server id 1  end_log_pos 162231 CRC32 0x118ac1c0   Anonymous_GTID  last_committed=237  sequence_number=238 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 162231
#171104  2:24:29 server id 1  end_log_pos 162318 CRC32 0x3c0650c0   Query   thread_id=33    exec_time=0 error_code=0
SET TIMESTAMP=1509762269/*!*/;
XA START X'32',X'',1
/*!*/;
# at 162318
#171104  2:24:29 server id 1  end_log_pos 162365 CRC32 0x73363da2   Table_map: `xa`.`t1` mapped to number 268
# at 162365
#171104  2:24:29 server id 1  end_log_pos 162410 CRC32 0x70f076b2   Write_rows: table id 268 flags: STMT_END_F

BINLOG '
3ST9WRMBAAAALwAAAD16AgAAAAwBAAAAAAMAAnhhAAJ0MQAC9vwDFAACAqI9NnM=
3ST9WR4BAAAALQAAAGp6AgAAAAwBAAAAAAEAAgAC//6AAAAAAAABTAiydvBw
'/*!*/;
### INSERT INTO `xa`.`t1`
### SET
###   @1=85000 /* DECIMAL(20,0) meta=5120 nullable=0 is_null=0 */
###   @2=NULL /* BLOB/TEXT meta=2 nullable=1 is_null=1 */
# at 162410
#171104  2:24:32 server id 1  end_log_pos 162493 CRC32 0x54ba2b15   Query   thread_id=33    exec_time=0 error_code=0
SET TIMESTAMP=1509762272/*!*/;
XA END X'32',X'',1
/*!*/;
# at 162493
#171104  2:24:32 server id 1  end_log_pos 162530 CRC32 0xfae9a150   XA PREPARE X'32',X'',1
XA PREPARE X'32',X'',1
/*!*/;
# at 162530
#171104  2:24:35 server id 1  end_log_pos 162595 CRC32 0x434b4469   Anonymous_GTID  last_committed=238  sequence_number=239 rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 162595
#171104  2:24:35 server id 1  end_log_pos 162683 CRC32 0xb21c1257   Query   thread_id=33    exec_time=0 error_code=0
SET TIMESTAMP=1509762275/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 162683
#171104  2:24:38 server id 1  end_log_pos 162748 CRC32 0x2b22a898   Anonymous_GTID  last_committed=239  sequence_number=240 rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 162748
#171104  2:24:38 server id 1  end_log_pos 162836 CRC32 0xc9c58814   Query   thread_id=33    exec_time=0 error_code=0
SET TIMESTAMP=1509762278/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 162836
#171104  2:25:52 server id 1  end_log_pos 162901 CRC32 0xa2774536   Anonymous_GTID  last_committed=240  sequence_number=241 rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 162901
#171104  2:25:52 server id 1  end_log_pos 163028 CRC32 0xef2c172d   Query   thread_id=33    exec_time=0 error_code=0
SET TIMESTAMP=1509762352/*!*/;
create table t3(t1_pk int primary key, t1_blob blob null)
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

You can see XA ROLLBACK is there twice.

If you do many xa rollbacks they will be all in the binary log:

#171104  2:27:39 server id 1  end_log_pos 163093 CRC32 0xc90c3a73       Anonymous_GTID  last_committed=241      sequence_number=242     rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 163093
#171104  2:27:38 server id 1  end_log_pos 163180 CRC32 0x9480da6f       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762458/*!*/;
XA START X'32',X'',1
/*!*/;
# at 163180
#171104  2:27:38 server id 1  end_log_pos 163227 CRC32 0xb28c4aec       Table_map: `xa`.`t1` mapped to number 268
# at 163227
#171104  2:27:38 server id 1  end_log_pos 163272 CRC32 0xa70b6aec       Write_rows: table id 268 flags: STMT_END_F

BINLOG '
miX9WRMBAAAALwAAAJt9AgAAAAwBAAAAAAMAAnhhAAJ0MQAC9vwDFAACAuxKjLI=
miX9WR4BAAAALQAAAMh9AgAAAAwBAAAAAAEAAgAC//6AAAAAAAABTAjsagun
'/*!*/;
### INSERT INTO `xa`.`t1`
### SET
###   @1=85000 /* DECIMAL(20,0) meta=5120 nullable=0 is_null=0 */
###   @2=NULL /* BLOB/TEXT meta=2 nullable=1 is_null=1 */
# at 163272
#171104  2:27:39 server id 1  end_log_pos 163355 CRC32 0x691f39ec       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762459/*!*/;
XA END X'32',X'',1
/*!*/;
# at 163355
#171104  2:27:39 server id 1  end_log_pos 163392 CRC32 0x0e88ffa2       XA PREPARE X'32',X'',1
XA PREPARE X'32',X'',1
/*!*/;
# at 163392
#171104  2:27:42 server id 1  end_log_pos 163457 CRC32 0x256a1c7c       Anonymous_GTID  last_committed=242      sequence_number=243     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 163457
#171104  2:27:42 server id 1  end_log_pos 163545 CRC32 0x3868e3f0       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762462/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 163545
#171104  2:27:43 server id 1  end_log_pos 163610 CRC32 0x51a750bb       Anonymous_GTID  last_committed=243      sequence_number=244     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 163610
#171104  2:27:43 server id 1  end_log_pos 163698 CRC32 0x6ed8cf68       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762463/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 163698
#171104  2:27:45 server id 1  end_log_pos 163763 CRC32 0xee5034df       Anonymous_GTID  last_committed=244      sequence_number=245     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 163763
#171104  2:27:45 server id 1  end_log_pos 163851 CRC32 0x9af01202       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762465/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 163851
#171104  2:27:46 server id 1  end_log_pos 163916 CRC32 0xc018a516       Anonymous_GTID  last_committed=245      sequence_number=246     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 163916
#171104  2:27:46 server id 1  end_log_pos 164004 CRC32 0xff24304d       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762466/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
# at 164004
#171104  2:27:48 server id 1  end_log_pos 164069 CRC32 0xfb16b1d2       Anonymous_GTID  last_committed=246      sequence_number=247     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 164069
#171104  2:27:48 server id 1  end_log_pos 164157 CRC32 0x1384b537       Query   thread_id=33    exec_time=0     error_code=0
SET TIMESTAMP=1509762468/*!*/;
XA ROLLBACK X'32',X'',1
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Suggested fix:
Do not put multiple XA ROLLBACK statements in the binlog

Hello Kenny,

Thank you for the report and test case.
Observed this with 5.7.20 build.

Thanks,
Umesh

test results

Attachment: 88358.results (application/octet-stream, text), 11.91 KiB.

Post by developer:
==================

This bug is marked as duplicate of bug#87393 which is fixed in 5.7.21 release.

Regards,
Venkatesh.