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
|
| Transition |
Time In Source Status |
Execution Times |
|
Open |
|
Confirmed |
|
5d 14h 50m
|
1
|
{"report":{"fcp":893.5,"ttfb":287.40000009536743,"pageVisibility":"visible","entityId":132700,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"d9c5b6dc-ab84-4eca-81ea-7d96d5c59d08","navigationType":0,"readyForUser":1010.8000001907349,"redirectCount":0,"resourceLoadedEnd":618.1000001430511,"resourceLoadedStart":296.10000014305115,"resourceTiming":[{"duration":39.09999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":296.10000014305115,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":296.10000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":335.2000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":39,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true","startTime":296.30000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":296.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":335.30000019073486,"responseStart":0,"secureConnectionStart":0},{"duration":207.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":296.5,"connectEnd":296.5,"connectStart":296.5,"domainLookupEnd":296.5,"domainLookupStart":296.5,"fetchStart":296.5,"redirectEnd":0,"redirectStart":0,"requestStart":337.80000019073486,"responseEnd":504.30000019073486,"responseStart":373.40000009536743,"secureConnectionStart":296.5},{"duration":320,"initiatorType":"script","name":"https://jira.mariadb.org/s/099b33461394b8015fc36c0a4b96e19f-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true","startTime":297,"connectEnd":297,"connectStart":297,"domainLookupEnd":297,"domainLookupStart":297,"fetchStart":297,"redirectEnd":0,"redirectStart":0,"requestStart":338.80000019073486,"responseEnd":617,"responseStart":378,"secureConnectionStart":297},{"duration":76,"initiatorType":"script","name":"https://jira.mariadb.org/s/94c15bff32baef80f4096a08aceae8bc-CDN/lu2bu7/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":297.10000014305115,"connectEnd":297.10000014305115,"connectStart":297.10000014305115,"domainLookupEnd":297.10000014305115,"domainLookupStart":297.10000014305115,"fetchStart":297.10000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":339.7000000476837,"responseEnd":373.10000014305115,"responseStart":371.60000014305115,"secureConnectionStart":297.10000014305115},{"duration":59.89999985694885,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":297.30000019073486,"connectEnd":297.30000019073486,"connectStart":297.30000019073486,"domainLookupEnd":297.30000019073486,"domainLookupStart":297.30000019073486,"fetchStart":297.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":340.5,"responseEnd":357.2000000476837,"responseStart":356.30000019073486,"secureConnectionStart":297.30000019073486},{"duration":61.799999952316284,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":297.30000019073486,"connectEnd":297.30000019073486,"connectStart":297.30000019073486,"domainLookupEnd":297.30000019073486,"domainLookupStart":297.30000019073486,"fetchStart":297.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":342.60000014305115,"responseEnd":359.10000014305115,"responseStart":357.60000014305115,"secureConnectionStart":297.30000019073486},{"duration":43.200000047683716,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2bu7/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":297.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":297.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":340.7000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":62.09999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":297.60000014305115,"connectEnd":297.60000014305115,"connectStart":297.60000014305115,"domainLookupEnd":297.60000014305115,"domainLookupStart":297.60000014305115,"fetchStart":297.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":343,"responseEnd":359.7000000476837,"responseStart":358.2000000476837,"secureConnectionStart":297.60000014305115},{"duration":45.200000047683716,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2bu7/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":297.7000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":297.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":342.90000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":63.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/3339d87fa2538a859872f2df449bf8d0-CDN/lu2bu7/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":297.80000019073486,"connectEnd":297.80000019073486,"connectStart":297.80000019073486,"domainLookupEnd":297.80000019073486,"domainLookupStart":297.80000019073486,"fetchStart":297.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":345.90000009536743,"responseEnd":361.40000009536743,"responseStart":359.2000000476837,"secureConnectionStart":297.80000019073486},{"duration":315.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":301.10000014305115,"connectEnd":301.10000014305115,"connectStart":301.10000014305115,"domainLookupEnd":301.10000014305115,"domainLookupStart":301.10000014305115,"fetchStart":301.10000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":391.40000009536743,"responseEnd":616.6000001430511,"responseStart":611.2000000476837,"secureConnectionStart":301.10000014305115},{"duration":316.90000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":301.2000000476837,"connectEnd":301.2000000476837,"connectStart":301.2000000476837,"domainLookupEnd":301.2000000476837,"domainLookupStart":301.2000000476837,"fetchStart":301.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":435.10000014305115,"responseEnd":618.1000001430511,"responseStart":613.8000001907349,"secureConnectionStart":301.2000000476837},{"duration":49.19999980926514,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":652.3000001907349,"connectEnd":652.3000001907349,"connectStart":652.3000001907349,"domainLookupEnd":652.3000001907349,"domainLookupStart":652.3000001907349,"fetchStart":652.3000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":670.4000000953674,"responseEnd":701.5,"responseStart":700.6000001430511,"secureConnectionStart":652.3000001907349},{"duration":229.60000014305115,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":887.2000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":887.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1116.8000001907349,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":65,"domainLookupEnd":109,"connectStart":109,"connectEnd":128,"secureConnectionStart":117,"requestStart":129,"responseStart":287,"responseEnd":300,"domLoading":291,"domInteractive":1070,"domContentLoadedEventStart":1070,"domContentLoadedEventEnd":1113,"domComplete":1387,"loadEventStart":1387,"loadEventEnd":1387,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1051.2000000476837},{"name":"bigPipe.sidebar-id.end","time":1052},{"name":"bigPipe.activity-panel-pipe-id.start","time":1052.1000001430511},{"name":"bigPipe.activity-panel-pipe-id.end","time":1052.9000000953674},{"name":"activityTabFullyLoaded","time":1128.7000000476837}],"measures":[],"correlationId":"9bad05cafed092","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":84,"dbReadsTimeInMs":16,"dbConnsTimeInMs":23,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Major