MySQL Bugs: #57119: XA transactions in prepared state cannot be rolled back or commited

Bug #57119	XA transactions in prepared state cannot be rolled back or commited
Submitted:	30 Sep 2010 6:12	Modified:	17 Dec 2011 17:37
Reporter:	Brett Cave	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.1.42, 5.1.51	OS:	Linux (centos5.4)
Assigned to:		CPU Architecture:	Any
Tags:	xa unknown_xid

Description:
The symptoms of this bug is similar to http://bugs.mysql.com/bug.php?id=44687

A database with an innodb table has some incomplete transactions, as shown by 'xa recover;':
mysql> xa recover;
+----------+--------------+--------------+--------------------------------------------------------------+
| formatID | gtrid_length | bqual_length | data                                                         |
+----------+--------------+--------------+--------------------------------------------------------------+
|   131075 |           31 |           29 | 1--3f57b3af:8546:4c6d3534:4146d-3f57b3af:8546:4c6d3534:41472 |
|   131075 |           31 |           29 | 1--3f57b3af:ed9a:4c3344f4:3a5e5-3f57b3af:ed9a:4c3344f4:3a5ea |
|   131075 |           31 |           29 | 1--3f57b3af:e5f1:4c4d506b:e551b-3f57b3af:e5f1:4c4d506b:e5520 |
|   131075 |           31 |           29 | 1--3f57b3af:bf85:4c43f444:1ac75-3f57b3af:bf85:4c43f444:1ac7a |
+----------+--------------+--------------+--------------------------------------------------------------+

These transactions cannot be rolled back or committed:

mysql> xa rollback '1--3f57b3af:8546:4c6d3534:4146d-3f57b3af:8546:4c6d3534:41472';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID

the server will not shut down either:
# mysqladmin ext | grep dirty
|     0|
# service mysql stop

Log shows:
100930  7:48:04 [Note] Event Scheduler: Purging the queue. 0 events
100930  7:48:04  InnoDB: Starting shutdown...

at which point it hangs. entire database is 6gb, and have left it running for 10 - 12 hours. disk IO stops and CPU idles.

kill -9 mysqld and restart the service, the server comes up within seconds:

100930 07:48:51 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
100930  7:48:51 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
100930  7:48:51  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Transaction 0 2093557 was in the XA prepared state.
InnoDB: Transaction 0 4945657 was in the XA prepared state.
InnoDB: Transaction 0 3969092 was in the XA prepared state.
InnoDB: Transaction 0 7661450 was in the XA prepared state.
InnoDB: 4 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 0 11215616
InnoDB: Last MySQL binlog file position 0 1001467149, file name ./qa-db-01-bin.000071
InnoDB: Starting in background the rollback of uncommitted transactions
100930  7:48:52  InnoDB: Rollback of non-prepared transactions completed
100930  7:48:52  InnoDB: Started; log sequence number 16 79539521
100930  7:48:52  InnoDB: Starting recovery for XA transactions...
100930  7:48:52  InnoDB: Transaction 0 7661450 in prepared state after recovery
100930  7:48:52  InnoDB: Transaction contains changes to 10 rows
100930  7:48:52  InnoDB: Transaction 0 4945657 in prepared state after recovery
100930  7:48:52  InnoDB: Transaction contains changes to 10 rows
100930  7:48:52  InnoDB: Transaction 0 3969092 in prepared state after recovery
100930  7:48:52  InnoDB: Transaction contains changes to 10 rows
100930  7:48:52  InnoDB: Transaction 0 2093557 in prepared state after recovery
100930  7:48:52  InnoDB: Transaction contains changes to 10 rows
100930  7:48:52  InnoDB: 4 transactions in prepared state after recovery
100930  7:48:52 [Note] Found 4 prepared transaction(s) in InnoDB
100930  7:48:52 [Warning] Found 4 prepared XA transactions
100930  7:48:52 [Note] Event Scheduler: Loaded 0 events
100930  7:48:52 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.42-community-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)

How to repeat:
From what I can tell, the mysqld was killed in the middle of XA transactions while the mount point that the datadir was mounted on had filled up.

Once these transactions are in the log, the symptoms occur.

Are you tried latest released version?.

no, will upgrade now to test and report back.

Upgraded to 5.1.51 and the old XA transaction is still being picked up. rollback is failing with the same error message.

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.1.51-community-log MySQL Community Server (GPL)

Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved.
This software comes with ABSOLUTELY NO WARRANTY. This is free software,
and you are welcome to modify and redistribute it under the GPL v2 license

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

mysql>
mysql>
mysql>
mysql> xa recover;
+----------+--------------+--------------+--------------------------------------------------------------+
| formatID | gtrid_length | bqual_length | data                                                         |
+----------+--------------+--------------+--------------------------------------------------------------+
|   131075 |           31 |           29 | 1--3f57b3af:8546:4c6d3534:4146d-3f57b3af:8546:4c6d3534:41472 |
|   131075 |           31 |           29 | 1--3f57b3af:ed9a:4c3344f4:3a5e5-3f57b3af:ed9a:4c3344f4:3a5ea |
|   131075 |           31 |           29 | 1--3f57b3af:e5f1:4c4d506b:e551b-3f57b3af:e5f1:4c4d506b:e5520 |
|   131075 |           31 |           29 | 1--3f57b3af:bf85:4c43f444:1ac75-3f57b3af:bf85:4c43f444:1ac7a |
+----------+--------------+--------------+--------------------------------------------------------------+
4 rows in set (0.00 sec)

mysql> xa rollback '1--3f57b3af:8546:4c6d3534:4146d-3f57b3af:8546:4c6d3534:41472';
ERROR 1397 (XAE04): XAER_NOTA: Unknown XID

Thank you for the feedback.

In the another bug report you wrote "The state occurred when either the disk that the mysql data dir was mounted on filled up or by killing the mysqld process without a clean shutdown." Could you please send us full error log file including information from that not clean shutdown? Please also inform us if you have repeatable test case to repeat the problem.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

adding logs.

We are also facing a similar kind of problem.

Looks like some race condition.

Following is the log snippet:

InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Transaction 0 143852 was in the XA prepared state.
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 0 144128
InnoDB: Last MySQL binlog file position 0 32660588, file name ./mysql-bin.000005
InnoDB: Starting in background the rollback of uncommitted transactions
110114 17:18:57  InnoDB: Rolling back trx with id 0 143785, 1 rows to undo
110114 17:18:57  InnoDB: Started; log sequence number 0 78644236
110114 17:18:57  InnoDB: Starting recovery for XA transactions...
110114 17:18:57  InnoDB: Transaction 0 143852 in prepared state after recovery
110114 17:18:57  InnoDB: Transaction contains changes to 2 rows
110114 17:18:57  InnoDB: 1 transactions in prepared state after recovery
110114 17:18:57 [Note] Found 1 prepared transaction(s) in InnoDB
110114 17:18:57 [Warning] Found 1 prepared XA transactions

InnoDB: Rolling back of trx id 0 143785 completed
110114 17:18:57  InnoDB: Rollback of non-prepared transactions completed
110114 17:18:58 [Note] Event Scheduler: Loaded 0 events
110114 17:18:58 [Note] /opt/mysql-enterprise-5.1.38-solaris10-sparc-64bit/bin/mysqld: ready for connections.
Version: '5.1.38-enterprise-commercial-pro-log'  socket: '/opt/cems/db/mysql/mysql.sock'  port: 3306  MySQL Enterprise Server - Pro Edition (Commercial)
110114 17:19:00 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=ebsc6b-relay-bin' to avoid this problem.
110114 17:19:00 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000005' at position 32660588, relay log './ebsc6b-relay-bin.000001' position: 4
110114 17:19:00 [Note] Slave I/O thread: connected to master 'replcems@192.168.100.25:3306',replication started in log 'mysql-bin.000005' at position 32660588
110114 17:19:00 [Note] /opt/mysql-enterprise-5.1.38-solaris10-sparc-64bit/bin/mysqld: Normal shutdown

110114 17:19:00 [Note] Event Scheduler: Purging the queue. 0 events
110114 17:19:00 [Note] Slave I/O thread killed while reading event
110114 17:19:00 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000005', position 33490608
110114 17:19:51 [ERROR] Slave SQL: Could not execute Write_rows event on table CEMSDB.HISTORICALALARMS; Lock wait timeout exceeded; try restarting transaction, Error_code: 1205; handler error HA_ERR_LOCK_WAIT_TIMEOUT; the event's master log mysql-bin.000005, end_log_pos 32661397, Error_code: 1205
110114 17:19:51 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.000005' at position 32660588
110114 17:19:51  InnoDB: Starting shutdown...
110114 18:21:58 mysqld_safe A mysqld process already exists

We are not able to shutdown the database thereafter. 
Shutdown of the database server hangs.

Looks like a duplicate of bug #59440. That should be fixed since 5.1.56 and 5.5.10.