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
|
{"report":{"fcp":687.7999999523163,"ttfb":149.90000009536743,"pageVisibility":"visible","entityId":132700,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":1,"journeyId":"74d6aadb-3426-4027-a173-3505c5839213","navigationType":0,"readyForUser":757.2000000476837,"redirectCount":0,"resourceLoadedEnd":804.0999999046326,"resourceLoadedStart":154.70000004768372,"resourceTiming":[{"duration":52.200000047683716,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":154.70000004768372,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":154.70000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":206.90000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":52,"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":155,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":155,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":207,"responseStart":0,"secureConnectionStart":0},{"duration":71,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":155.09999990463257,"connectEnd":155.09999990463257,"connectStart":155.09999990463257,"domainLookupEnd":155.09999990463257,"domainLookupStart":155.09999990463257,"fetchStart":155.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":155.09999990463257,"responseEnd":226.09999990463257,"responseStart":226.09999990463257,"secureConnectionStart":155.09999990463257},{"duration":151,"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":155.29999995231628,"connectEnd":155.29999995231628,"connectStart":155.29999995231628,"domainLookupEnd":155.29999995231628,"domainLookupStart":155.29999995231628,"fetchStart":155.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":155.29999995231628,"responseEnd":306.2999999523163,"responseStart":306.2999999523163,"secureConnectionStart":155.29999995231628},{"duration":147.40000009536743,"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":155.29999995231628,"connectEnd":155.29999995231628,"connectStart":155.29999995231628,"domainLookupEnd":155.29999995231628,"domainLookupStart":155.29999995231628,"fetchStart":155.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":155.29999995231628,"responseEnd":302.7000000476837,"responseStart":302.7000000476837,"secureConnectionStart":155.29999995231628},{"duration":151.20000004768372,"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":155.5,"connectEnd":155.5,"connectStart":155.5,"domainLookupEnd":155.5,"domainLookupStart":155.5,"fetchStart":155.5,"redirectEnd":0,"redirectStart":0,"requestStart":155.5,"responseEnd":306.7000000476837,"responseStart":306.7000000476837,"secureConnectionStart":155.5},{"duration":151.5,"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":155.59999990463257,"connectEnd":155.59999990463257,"connectStart":155.59999990463257,"domainLookupEnd":155.59999990463257,"domainLookupStart":155.59999990463257,"fetchStart":155.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":155.59999990463257,"responseEnd":307.09999990463257,"responseStart":307.09999990463257,"secureConnectionStart":155.59999990463257},{"duration":151.79999995231628,"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":155.70000004768372,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":155.70000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":307.5,"responseStart":0,"secureConnectionStart":0},{"duration":152.10000014305115,"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":155.79999995231628,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":155.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":307.90000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":151.70000004768372,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":155.79999995231628,"connectEnd":155.79999995231628,"connectStart":155.79999995231628,"domainLookupEnd":155.79999995231628,"domainLookupStart":155.79999995231628,"fetchStart":155.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":155.79999995231628,"responseEnd":307.5,"responseStart":307.5,"secureConnectionStart":155.79999995231628},{"duration":152.09999990463257,"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":155.90000009536743,"connectEnd":155.90000009536743,"connectStart":155.90000009536743,"domainLookupEnd":155.90000009536743,"domainLookupStart":155.90000009536743,"fetchStart":155.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":155.90000009536743,"responseEnd":308,"responseStart":308,"secureConnectionStart":155.90000009536743},{"duration":338.7000000476837,"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":168,"connectEnd":168,"connectStart":168,"domainLookupEnd":168,"domainLookupStart":168,"fetchStart":168,"redirectEnd":0,"redirectStart":0,"requestStart":168,"responseEnd":506.7000000476837,"responseStart":506.7000000476837,"secureConnectionStart":168},{"duration":444.39999985694885,"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":174.90000009536743,"connectEnd":174.90000009536743,"connectStart":174.90000009536743,"domainLookupEnd":174.90000009536743,"domainLookupStart":174.90000009536743,"fetchStart":174.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":174.90000009536743,"responseEnd":619.2999999523163,"responseStart":619.2999999523163,"secureConnectionStart":174.90000009536743},{"duration":131.40000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":439.59999990463257,"connectEnd":439.59999990463257,"connectStart":439.59999990463257,"domainLookupEnd":439.59999990463257,"domainLookupStart":439.59999990463257,"fetchStart":439.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":439.59999990463257,"responseEnd":571,"responseStart":571,"secureConnectionStart":439.59999990463257},{"duration":164.29999995231628,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2bu7/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true","startTime":635.2000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":635.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":799.5,"responseStart":0,"secureConnectionStart":0},{"duration":164.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/e65b778d185daf5aee24936755b43da6/_/download/contextbatch/js/browser-metrics-plugin.contrib,-_super,-project.issue.navigator,-jira.view.issue,-atl.general/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true","startTime":636,"connectEnd":636,"connectStart":636,"domainLookupEnd":636,"domainLookupStart":636,"fetchStart":636,"redirectEnd":0,"redirectStart":0,"requestStart":636,"responseEnd":800.5999999046326,"responseStart":800.5999999046326,"secureConnectionStart":636},{"duration":167.69999980926514,"initiatorType":"script","name":"https://jira.mariadb.org/s/f51ef5507eea4c158f257c66c93b2a3f-CDN/lu2bu7/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/js/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true","startTime":636.4000000953674,"connectEnd":636.4000000953674,"connectStart":636.4000000953674,"domainLookupEnd":636.4000000953674,"domainLookupStart":636.4000000953674,"fetchStart":636.4000000953674,"redirectEnd":0,"redirectStart":0,"requestStart":636.4000000953674,"responseEnd":804.0999999046326,"responseStart":804.0999999046326,"secureConnectionStart":636.4000000953674},{"duration":146.5,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":667.0999999046326,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":667.0999999046326,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":813.5999999046326,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":11,"responseStart":150,"responseEnd":175,"domLoading":153,"domInteractive":822,"domContentLoadedEventStart":822,"domContentLoadedEventEnd":860,"domComplete":1574,"loadEventStart":1574,"loadEventEnd":1576,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":796.4000000953674},{"name":"bigPipe.sidebar-id.end","time":797.0999999046326},{"name":"bigPipe.activity-panel-pipe-id.start","time":797.2000000476837},{"name":"bigPipe.activity-panel-pipe-id.end","time":799.5999999046326},{"name":"activityTabFullyLoaded","time":879.5}],"measures":[],"correlationId":"9c7cd9ad27c48f","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":77,"dbReadsTimeInMs":10,"dbConnsTimeInMs":18,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Bug
Major