Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Critical
-
Resolution: Unresolved
-
10.6.20
-
None
-
Q2/2026 Server Maintenance
Description
We noticed that after switching parallel replication mode of our replicas from conservative to optimistic, the restore almost always fails with the infamous error:
Found 5 prepared transactions! It means that server was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a crash. You have to start server with --tc-heuristic-recover switch to commit or rollback pending transactions.
|
This only happens when the replica we take a backup from has optimistic replication enabled. Needless to say we aren't using XA transactions, we do however use prepared statements on the upstairs master.
I was able to reproduce this more or less consistently (meaning it will pass about only one out of 10 times I try, while normally failing with the above error).
How to reproduce:
On one node, install MariaDB and sysbench. Use sysbench cmd line below.
sysbench --threads=32 --db-ps-mode=auto --tables=8 --time=3600 --mysql-host='localhost' --mysql-user='root' /usr/share/sysbench/oltp_read_write.lua run
|
Master's non-default MariaDB config :
transaction_isolation='READ-COMMITTED'
|
On another node, set up a replica.
Non-default config:
slave_parallel_threads=16
|
transaction_isolation='READ-COMMITTED'
|
log_bin='binlog'
|
log_slave_updates
|
While sysbench runs on master, take a streaming backup from the replica to a 3rd server where you want to restore:
mariabackup --backup --stream mbstream --slave-info --parallel 8 | ssh -q 10.211.55.17 mbstream -x -v -C /var/lib/mysql
|
On the target server, try to restore the backup:
mariabackup --prepare --use-memory=400M --target-dir=/var/lib/mysql
|
chown -R mysql:mysql /var/lib/mysql/
|
systemctl start mariadb.service
|
Startup fails.
Example:
2025-02-04 19:34:56 0 [Note] Starting MariaDB 10.6.20-MariaDB source revision f00711bba2cd383825d0be1867f7d7d7f641c9e4 server_uid wv/6js4vd2mPJW/WB5ScVJ/uod0= as process 5714
|
2025-02-04 19:34:56 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
|
2025-02-04 19:34:56 0 [Note] InnoDB: Number of pools: 1
|
2025-02-04 19:34:56 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
|
2025-02-04 19:34:56 0 [Note] InnoDB: Using Linux native AIO
|
2025-02-04 19:34:56 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
|
2025-02-04 19:34:56 0 [Note] InnoDB: Completed initialization of buffer pool
|
2025-02-04 19:34:56 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 100663296 bytes
|
2025-02-04 19:34:56 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
|
2025-02-04 19:34:56 0 [Note] InnoDB: New log file created, LSN=52293475656
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471403 was in the XA prepared state.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471419 was in the XA prepared state.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471422 was in the XA prepared state.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471423 was in the XA prepared state.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471426 was in the XA prepared state.
|
2025-02-04 19:34:56 0 [Note] InnoDB: 14 transaction(s) which must be rolled back or cleaned up in total 45 row operations to undo
|
2025-02-04 19:34:56 0 [Note] InnoDB: Trx id counter is 25471435
|
2025-02-04 19:34:56 0 [Note] InnoDB: 128 rollback segments are active.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2025-02-04 19:34:56 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2025-02-04 19:34:56 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
|
2025-02-04 19:34:56 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2025-02-04 19:34:56 0 [Note] InnoDB: 10.6.20 started; log sequence number 0; transaction id 25471436
|
2025-02-04 19:34:56 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2025-02-04 19:34:56 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
|
2025-02-04 19:34:56 0 [Note] InnoDB: Cannot open '/var/lib/mysql/ib_buffer_pool' for reading: No such file or directory
|
2025-02-04 19:34:56 0 [Note] InnoDB: Rolled back recovered transaction 25471404
|
2025-02-04 19:34:56 0 [Note] InnoDB: Rolled back recovered transaction 25471420
|
2025-02-04 19:34:56 0 [Note] InnoDB: Starting recovery for XA transactions...
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471403 in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction contains changes to 5 rows
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471423 in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction contains changes to 5 rows
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471419 in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction contains changes to 5 rows
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471426 in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction contains changes to 5 rows
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction 25471422 in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] InnoDB: Transaction contains changes to 5 rows
|
2025-02-04 19:34:56 0 [Note] InnoDB: 5 transactions in prepared state after recovery
|
2025-02-04 19:34:56 0 [Note] Found 5 prepared transaction(s) in InnoDB
|
2025-02-04 19:34:56 0 [ERROR] Found 5 prepared transactions! It means that server was not shut down properly last time and critical recovery information (last binlog or tc.log file) was manually deleted after a crash. You have to start server with --tc-heuristic-recover switch to commit or rollback pending transactions.
|
2025-02-04 19:34:56 0 [ERROR] Aborting
|
Attachments
Issue Links
- relates to
-
MDEV-38684 Handling Internal XA Recovery and --tc-heuristic-recover in Automated Snapshot Restores
-
- Open
-