Details
-
Bug
-
Status: Confirmed (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.6.20
-
None
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
Activity
Hey Kristian, thanks for your detailed analysis.
However, I feel that mariabackup --prepare should leave us with a ready-to-start database when it completes successfully, while this is not the case here.
And while you say that this can always happen , well in my experience it never actually happened, unless there was a bug (eg. with early Galera versions).
In any case, how can a DBA know whether the transaction(s) should be committed or rolled back? We are restoring a backup here and we want it to be consistent, and
not the result of DBA's guesswork.... you suggest to always start in manual rollback mode - does that guarantee a consistent backup (meaning the resulting dataset
is guaranteed to have same data as the source at the backup point in time)?
We are using 10.6.20 , server and utilities.
Thanks,
Rick
odiogoogle Agree, this is something mariabackup should handle, I am not sure why it does not. Hopefully Marko or Vlad knows how mariabackup is meant to handle this.
With "can always happen", I meant that it is normal for the server to be in a state where there are prepared internal XA transactions, not that mariabackup should ignore this state and leave it for the user to handle.
Rolling back the transactions on the restored server should be correct, since these transactions were not committed on the original server (and may never be committed). And there is no binlog in the backup to be consistent with. The transactions will later be replicated (if committed on the master) if the restored server is set up as a slave. But again, this is something mariabackup ought to handle.
I hope that wlad can answer this. I’m not at all familiar with the binlog or how mariadb-backup would handle it. Could it be that something around backup locks (MDEV-19749) needs to be refined?
If backup locks are supposed to prevent there being any internal XA transactions in the "prepared" state at the time of the backup completion, then yes, it might be related to backup locks, which IIRC there is special handling for in parallel replication. But I do not know if such requirement exists on the backup locks.
In any case, that will not help for external XA transactions in the prepared state, which cannot be prevented by backup locks IIUC. After removal of the --rollback-xa option, I think such transactions will be left dangling on the restored server, where they are unlikely to be useful and will need to be rolled back manually by the user. (This particular reported issue is not related to external XA though).
I can't answer this , because I was not maintaining mariabackup anymore, when rollback-xa was introduced , in MDEV-21168 . But vlad.lesin maybe can answer. The corresponding commit says in comment, it must NOT be ported to 10.5+, but I frankly have no idea what's talking about 
I asked Monty about this, who has worked on the backup locks.
Monty agreed that the correct behaviour here is for mariabackup to automatically roll back those "5 prepared transactions" during mariabackup --prepare, so the restored server can start without any special manual user intervention.
Ideally, this should also happen for external XA transactions, however that would currently break provisioning a new slave from a mariabackup due to MDEV-32020. But for internal XA transactions (as in this report), rolling back is correct.
It is normal to have prepared transactions pending inside InnoDB when the binlog is enabled. This happens because the server uses internal XA transactions to do two-phase commit between InnoDB and the binlog to ensure consistency in case of a server crash.
Thus, this is probably not directly related to optimistic parallel replication, except that optimistic parallel replication runs a lot more transactions in parallel and can thus have more transactions in the "prepared" state at the time of a crash (or mariabackup snapshot)
During normal crash recovery, the binlog is consulted to decide how to handle these transactions. But since the binlogs are not included in the mariabackup, the server cannot use this method and gives the described error instead.
A work-around is to start the restored server with --tc-heuristic-recover=rollback (on first start only).
There used to be an option --rollback-xa for mariabackup that could be used to handle this, but it is removed since 10.5. Which version of mariabackup are you using to take the backup?
marko, wlad, does one of you know if mariabackup is supposed to handle this automatically (ie. roll back any internal XA transactions in InnoDB during --prepare), or how else the issue of pending internal XA transactions are supposed to be handled in the restored server which is missing the binlogs to do crash recovery?