XA_PREPARED transaction rollbacked when client disconnect

[fengyi]

This is a konwn issue, see http://bugs.mysql.com/bug.php?id=12161

MySQL xa transaction has the following limitaitons:
1. when client disconnects, XA_PREPARED transaction will be rollbacked.
2. when server crashes, XA_PREPARED transactions can be found by 'XA RECOVER' and commit/rollback, but binlog are lost, which breaks the replication.

2. is caused by the the optimization of binlog(no prepared log) , so that is not easy to fix.

but 1. can be solved and there is no need to change any logic of binlog when fixing it, in http://bugs.mysql.com/bug.php?id=12161, feng shao proposed a solution as *ha_semi_rollback_trans*, which suspends the INNODB transaction for later commit/rollback, but it lost the binlog as 2.

I have an idea to solve 1. while keep the binlog: suspend the disconnecting *thd* for later commit/rollback. The following is effect of the patch:

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

mysql> reset master;
Query OK, 0 rows affected (0.34 sec)

mysql> show master logs;
+------------------+-----------+
| Log_name | File_size |
+------------------+-----------+
| mysql-bin.000001 | 107 |
+------------------+-----------+
1 row in set (0.00 sec)

mysql> show create table test.t\G
*************************** 1. row ***************************
       Table: t
Create Table: CREATE TABLE `t` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `num` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=gbk
1 row in set (0.00 sec)

mysql> select * from test.t;
+----+------+
| id | num |
+----+------+
| 1 | 1 |
+----+------+
1 row in set (0.00 sec)

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

mysql> insert into test.t(num) values(2);
Query OK, 1 row affected (0.00 sec)

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

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

mysql> quit
Bye

*********************** another session *********************

$bin/mysql -uroot -S run/mysql.sock
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 4096
Server version: 5.5.18-tb3633-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show processlist\G
*************************** 1. row ***************************
           Id: 4095
         User: root
         Host: localhost
           db: NULL
      Command: Killed
         Time: 17
        State: Waiting for xa commit/rollback
         Info: NULL
    Rows_sent: 0
Rows_examined: 0
    Rows_read: 2
*************************** 2. row ***************************
           Id: 4096
         User: root
         Host: localhost
           db: NULL
      Command: Query
         Time: 0
        State: NULL
         Info: show processlist
    Rows_sent: 0
Rows_examined: 0
    Rows_read: 1
2 rows in set (0.00 sec)

mysql> xa recover;
+----------+--------------+--------------+------+
| formatID | gtrid_length | bqual_length | data |
+----------+--------------+--------------+------+
| 1 | 4 | 0 | xa_2 |
+----------+--------------+--------------+------+
1 row in set (0.00 sec)

mysql> xa commit 'xa_2';
Query OK, 0 rows affected (0.00 sec)

mysql> select * from test.t;
+----+------+
| id | num |
+----+------+
| 1 | 1 |
| 2 | 2 |
+----+------+
2 rows in set (0.00 sec)

mysql> xa recover;
Empty set (0.00 sec)

mysql> show processlist\G
*************************** 1. row ***************************
           Id: 4096
         User: root
         Host: localhost
           db: NULL
      Command: Query
         Time: 0
        State: NULL
         Info: show processlist
    Rows_sent: 0
Rows_examined: 0
    Rows_read: 3
1 row in set (0.00 sec)

mysql> show binlog events in 'mysql-bin.000001';
+------------------+-----+-------------+-----------+-------------+----------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+-----+-------------+-----------+-------------+----------------------------------------------+
| mysql-bin.000001 | 4 | Format_desc | 1 | 107 | Server ver: 5.5.18-tb3633-log, Binlog ver: 4 |
| mysql-bin.000001 | 107 | Query | 1 | 171 | BEGIN |
| mysql-bin.000001 | 171 | Table_map | 1 | 212 | table_id: 186 (test.t) |
| mysql-bin.000001 | 212 | Write_rows | 1 | 250 | table_id: 186 flags: STMT_END_F |
| mysql-bin.000001 | 250 | Query | 1 | 315 | COMMIT |
+------------------+-----+-------------+-----------+-------------+----------------------------------------------+
5 rows in set (0.00 sec)

bin/mysqlbinlog -vvv log/mysql-bin.000001
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#130723 19:31:56 server id 1 end_log_pos 107 Start: binlog v 4, server v 5.5.18-tb3633-log created 130723 19:31:56 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
rGnuUQ8BAAAAZwAAAGsAAAABAAQANS41LjE4LXRiMzYzMy1sb2cAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAACsae5REzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 107
#130723 19:33:39 server id 1 end_log_pos 171 Query thread_id=4095 exec_time=48 error_code=0
SET TIMESTAMP=1374579219/*!*/;
SET @@session.pseudo_thread_id=4095/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=28/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 171
# at 212
#130723 19:33:00 server id 1 end_log_pos 212 Table_map: `test`.`t` mapped to number 186
#130723 19:33:00 server id 1 end_log_pos 250 Write_rows: table id 186 flags: STMT_END_F

BINLOG '
7GnuURMBAAAAKQAAANQAAAAAALoAAAAAAAEABHRlc3QAAXQAAgMDAAI=
7GnuURcBAAAAJgAAAPoAAAAAALoAAAAAAAEAAv/8AgAAAAIAAAA=
'/*!*/;
### INSERT INTO test.t
### SET
### @1=2 /* INT meta=0 nullable=0 is_null=0 */
### @2=2 /* INT meta=0 nullable=1 is_null=0 */
# at 250
#130723 19:33:39 server id 1 end_log_pos 315 Query thread_id=4095 exec_time=48 error_code=0
SET TIMESTAMP=1374579219/*!*/;
COMMIT
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Hope someone can review the patch for me .

Thanks.

[fengyi (fengyi)]

This patch is based on Percona server 5.5.18

[Nilnandan Joshi (nilnandan-joshi)]

Reproduce with PS 5.6.15

mysql> create table t1(a int);
Query OK, 0 rows affected (0.05 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t1 values (1);
Query OK, 1 row affected (0.00 sec)

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

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

mysql> ^CCtrl-C -- exit!
Aborted
root@Nil-Dell-XPS:/etc# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 52
Server version: 5.6.15-63.0 Percona Server (GPL), Release 63.0

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> xa recover;
Empty set (0.00 sec)

mysql>

[Nilnandan Joshi (nilnandan-joshi)]

Reproduce with 5.1.71

mysql> use test
Database changed
mysql> create table t1(a int);
Query OK, 0 rows affected (0.02 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t1 values (1);
Query OK, 1 row affected (0.00 sec)

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

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

mysql> Ctrl-C -- exit!
Aborted
nilnandan@Nil-Dell-XPS:~/sandboxes/msb_5_1_71$ mysql -umsandbox -p --socket=/tmp/mysql_sandbox5171.sock
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.1.71rel14.9 Percona Server with XtraDB (GPL), Release rel14.9, Revision 589

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>
mysql> xa recover;
Empty set (0.00 sec)

mysql>

[Nilnandan Joshi (nilnandan-joshi)]

Reproduce with 5.5.35

mysql> create table t2(a int);
Query OK, 0 rows affected (0.02 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t2 values (1);
Query OK, 1 row affected (0.00 sec)

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

mysql> xa prepare 'test';
Query OK, 0 rows affected (0.01 sec)

mysql> Ctrl-C -- exit!
Aborted
root@Nil-Dell-XPS:/var/lib/mysql# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 41
Server version: 5.5.35-33.0 Percona Server (GPL), Release 33.0

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> xa recover;
Empty set (0.00 sec)

mysql>

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1401