[MDEV-23081] after restoring backup taken from a galera node, stray XA transactions remain at startup Created: 2020-07-03  Updated: 2020-10-21  Resolved: 2020-10-21

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Server
Affects Version/s: 10.4.13
Fix Version/s: 10.4.16, 10.5.7, 10.6.0

Type: Bug Priority: Critical
Reporter: Rick Pizzi Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 1
Labels: None


 Description   

A typical use case is to use mariabackup to take a live backup from a running galera node and use that to build an async slave to be used for backup or reporting purposes.

After restoring such backup and running mariabackup --prepare, it appears that when mariadb is started some stray internal XA transactions from WSREP remain in the prepared state and will never go away. These can also take row locks and conflict with replication or other legit traffic.

Only way to have them disappear is to run XA ROLLBACK on each of them.

When server is started, if wsrep is OFF, these should be cleaned up automatically to avoid issues.

Log from node startup below.

Thanks
Rick

2020-07-03  9:03:16 0 [Note] mysqld: Aria engine: starting recovery
 
recovered pages: 0% 100% (0.0 seconds); tables to flush: 1 0
 
 (0.0 seconds);
 
2020-07-03  9:03:16 0 [Note] mysqld: Aria engine: recovery done
 
2020-07-03  9:03:16 0 [Warning] option 'innodb-print-all-deadlocks': boolean value 'yes' wasn't recognized. Set to OFF.
 
2020-07-03  9:03:16 0 [Note] InnoDB: Using Linux native AIO
 
2020-07-03  9:03:16 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-07-03  9:03:16 0 [Note] InnoDB: Uses event mutexes
 
2020-07-03  9:03:16 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-07-03  9:03:16 0 [Note] InnoDB: Number of pools: 1
 
2020-07-03  9:03:16 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2020-07-03  9:03:16 0 [Note] InnoDB: Initializing buffer pool, total size = 10G, instances = 4, chunk size = 128M
 
2020-07-03  9:03:16 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-07-03  9:03:16 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-07-03  9:03:16 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
 
2020-07-03  9:03:16 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
 
2020-07-03  9:03:16 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
 
2020-07-03  9:03:16 0 [Note] InnoDB: New log files created, LSN=39006842777638
 
2020-07-03  9:03:16 0 [Note] InnoDB: Transaction 36671586166 was in the XA prepared state.
 
2020-07-03  9:03:16 0 [Note] InnoDB: Transaction 36671586169 was in the XA prepared state.
 
2020-07-03  9:03:16 0 [Note] InnoDB: Transaction 36671586170 was in the XA prepared state.
 
2020-07-03  9:03:16 0 [Note] InnoDB: 4 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
 
2020-07-03  9:03:16 0 [Note] InnoDB: Trx id counter is 36671586173
 
2020-07-03  9:03:16 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2020-07-03  9:03:16 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
 
2020-07-03  9:03:16 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-07-03  9:03:16 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-07-03  9:03:16 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-07-03  9:03:16 0 [Note] InnoDB: Waiting for purge to start
 
2020-07-03  9:03:16 0 [Note] InnoDB: Rolled back recovered transaction 36671586172
 
2020-07-03  9:03:16 0 [Note] InnoDB: Rollback of non-prepared transactions completed
 
2020-07-03  9:03:17 0 [Note] InnoDB: 10.4.13 started; log sequence number 39006842778124; transaction id 36671586176
 
2020-07-03  9:03:17 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2020-07-03  9:03:17 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-07-03  9:03:17 0 [Note] InnoDB: Starting recovery for XA transactions...
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction 36671586170 in prepared state after recovery
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction contains changes to 1 rows
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction 36671586166 in prepared state after recovery
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction contains changes to 1 rows
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction 36671586169 in prepared state after recovery
 
2020-07-03  9:03:17 0 [Note] InnoDB: Transaction contains changes to 1 rows
 
2020-07-03  9:03:17 0 [Note] InnoDB: 3 transactions in prepared state after recovery
 
2020-07-03  9:03:17 0 [Note] Found 3 prepared transaction(s) in InnoDB
 
2020-07-03  9:03:17 0 [Warning] Found 3 prepared XA transactions
 
2020-07-03  9:03:17 0 [Note] Server socket created on IP: '::'.
 
2020-07-03  9:03:17 0 [Warning] 'user' entry 'root@te-db01.test.local' ignored in --skip-name-resolve mode.
 
2020-07-03  9:03:17 0 [Warning] 'proxies_priv' entry '@% root@te-db01.test.local' ignored in --skip-name-resolve mode.
 
2020-07-03  9:03:17 0 [Note] Reading of all Master_info entries succeeded
 
2020-07-03  9:03:17 0 [Note] Added new Master_info '' to hash table
 
2020-07-03  9:03:17 0 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.4.13-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server



 Comments   
Comment by Rick Pizzi [ 2020-07-03 ]

After over 40 minutes since server startup, these are still there:

------------
 
TRANSACTIONS
 
------------
 
Trx id counter 36671586272
 
Purge done for trx's n:o < 36671586262 undo n:o < 0 state: running
 
History list length 1
 
LIST OF TRANSACTIONS FOR EACH SESSION:
 
---TRANSACTION 421184685794264, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685819800, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685815544, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685811288, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685798520, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685790008, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 421184685785752, not started
 
0 lock struct(s), heap size 1128, 0 row lock(s)
 
---TRANSACTION 36671586170, ACTIVE (PREPARED) 3441 sec recovered trx
 
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1
 
---TRANSACTION 36671586169, ACTIVE (PREPARED) 3441 sec recovered trx
 
1 lock struct(s), heap size 1128, 0 row lock(s), undo log entries 1
 
---TRANSACTION 36671586166, ACTIVE (PREPARED) 3441 sec recovered trx
 
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1

Comment by Rick Pizzi [ 2020-07-03 ]

Evidence that these are WSREP related transactions:

mysql>xa recover;
 
+----------+--------------+--------------+----------------------------------+
 
| formatID | gtrid_length | bqual_length | data                             |
 
+----------+--------------+--------------+----------------------------------+
 
|        1 |           32 |            0 | WSREPXie4?j????
 
                                                          o?lr??*N              |
 
|        1 |           32 |            0 | WSREPXie4?j????
 
                                                          o?lr??)N              |
 
|        1 |           32 |            0 | WSREPXie4?j????
 
                                                          o?lr??+N              |
 
+----------+--------------+--------------+----------------------------------+
 
3 rows in set (0.000 sec)
 
mysql> XA RECOVER FORMAT='SQL' ;
 
+----------+--------------+--------------+---------------------------------------------------------------------+
 
| formatID | gtrid_length | bqual_length | data                                                                |
 
+----------+--------------+--------------+---------------------------------------------------------------------+
 
|        1 |           32 |            0 | X'5753524550586965349c6abfb5b111eab90c6f9f6c72e4dc2a074e1c00000000' |
 
|        1 |           32 |            0 | X'5753524550586965349c6abfb5b111eab90c6f9f6c72e4dc29074e1c00000000' |
 
|        1 |           32 |            0 | X'5753524550586965349c6abfb5b111eab90c6f9f6c72e4dc2b074e1c00000000' |
 
+----------+--------------+--------------+---------------------------------------------------------------------+
 
3 rows in set (0.004 sec)

Comment by Daniele Sciascia [ 2020-10-20 ]

I submitted a pull request for this issue here: https://github.com/MariaDB/server/pull/1684

With this change, XA transactions with "WSREP" prefixed xids will be rolled back on restart when wsrep_on=OFF.

Generated at Thu Feb 08 09:19:42 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.