10.4 30da40bb8c30
|
mariabackup: cd to /data/bld/10.4/backup/
|
ERROR : File ./test/seq5.ren was not found, but expected during rename processing
|
2019-01-09 15:04:51 0x7f6ed8e60740 InnoDB: Assertion failure in file /data/src/10.4/extra/mariabackup/xtrabackup.cc line 5390
|
InnoDB: Failing assertion: 0
|
|
#5 0x000055ef2abf4edf in ut_dbg_assertion_failed (expr=0x55ef2ae277f6 "0", file=0x55ef2ae21fd0 "/data/src/10.4/extra/mariabackup/xtrabackup.cc", line=5390) at /data/src/10.4/storage/innobase/ut/ut0dbg.cc:60
|
#6 0x000055ef2a1479c1 in rename_table_in_prepare (datadir=".", from="test/seq4", to="test/seq5", extension=0x55ef2ae26cd2 ".ibd") at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5390
|
#7 0x000055ef2a1476e7 in rename_table_in_prepare (datadir=".", from="test/seq4", to="test/seq5", extension=0x0) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5379
|
#8 0x000055ef2a147f13 in prepare_handle_ren_files (datadir=0x55ef2ae26481 ".", db=0x7fff454cbe50 "test", filename=0x7fff454cce30 "seq4.ren") at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5414
|
#9 0x000055ef2a147269 in xb_process_datadir (path=0x55ef2ae26481 ".", suffix=0x55ef2ae277aa ".ren", func=0x55ef2a147c61 <prepare_handle_ren_files(char const*, char const*, char const*, void*)>) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5272
|
#10 0x000055ef2a1484ea in xtrabackup_prepare_func (argv=0x55ef2cdeba88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5462
|
#11 0x000055ef2a14abda in main_low (argv=0x55ef2cdeba88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6418
|
#12 0x000055ef2a14a3ee in main (argc=4, argv=0x7fff454ce7f8) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6211
|
The backup datadir on which the failure can be observed is available here:
ftp://ftp.askmonty.org/public/mdev18185-backup.tar.gz
It was stored after a failed --prepare attempt, hopefully it didn't corrupt it further. At least next attempts end with the same failure as the initial one.
To reproduce, just run mariabackup --prepare on it.
Notes on the origin of the report. Please be aware it's not easily reproducible the same way, the test is concurrent by nature, and apparently there is a race condition involved.
The problem initially happened by running the concurrent test with MariaBackupFull scenario:
github.com/MariaDB/randgen elenst-dev 5342873c97, github.com/elenst/mariadb-toolbox master 6ded4b71568
|
perl ./runall-new.pl --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir --duration=350 --threads=4 --seed=1547032787 --reporters=Backtrace,ErrorLog,Deadlock --skip-gendata --gendata-advanced --views --grammar=conf/mariadb/generic-dml.yy --redefine=conf/mariadb/bulk_insert.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --filter=/home/travis/mariadb-toolbox/travis/10.4-combo-filter.ff --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--aria-encrypt-tables=1 --mysqld=--encrypt-tmp-disk-tables=1 --mysqld=--file-key-management --mysqld=--file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --mysqld=--plugin-load-add=file_key_management --engine=Aria --scenario=MariaBackupFull --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/sequences.yy
|
The test performs the following steps:
- start the server with
/home/travis/server/bin/mysqld --no-defaults --basedir=/home/travis/server --lc-messages-dir=/home/travis/server/share --character-sets-dir=/home/travis/server/share/charsets --tmpdir=/home/travis/logs/vardir/tmp --core-file --datadir=/home/travis/logs/vardir/data --max-allowed-packet=128Mb --port=19300 --socket=/home/travis/logs/vardir/mysql.sock --pid-file=/home/travis/logs/vardir/mysql.pid --general-log --general-log-file=/home/travis/logs/vardir/mysql.log --log_output=FILE --max-statement-time=20 --lock-wait-timeout=10 --loose-innodb-lock-wait-timeout=5 --loose-debug_assert_on_not_freed_memory=0 --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --file-key-management --file-key-management-filename=/home/travis/mariadb-toolbox/data/keys.txt --plugin-load-add=file_key_management
|
- run concurrent DML/DDL flow on the server;
- after ~100 seconds, take the full backup from the running server (succeeded, the log attached as mbackup_backup.log
;
- after another ~100 seconds, shut down the server gracefully (succeeded, the error log is attached as mysql.err_orig
;
- attempt to run mariabackup --prepare failed, the log attached as mbackup_prepare.log
;
I have no information yet whether the problem happens on earlier versions.
- relates to
-
MDEV-18201
InnoDB: Operating system error number 2 in a file operation and InnoDB: Cannot open datafile for read-only upon startup on datadir restored from full backup
-
-
Closed
{"report":{"fcp":1106.6999998092651,"ttfb":284.59999990463257,"pageVisibility":"visible","entityId":71772,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"baeadaaf-895f-4d80-a527-85cdbf07ee75","navigationType":0,"readyForUser":1264.5,"redirectCount":0,"resourceLoadedEnd":1029,"resourceLoadedStart":294.40000009536743,"resourceTiming":[{"duration":105.59999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":294.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":294.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":400,"responseStart":0,"secureConnectionStart":0},{"duration":106.19999980926514,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/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&whisper-enabled=true","startTime":294.80000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":294.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":401,"responseStart":0,"secureConnectionStart":0},{"duration":225.09999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":295,"connectEnd":295,"connectStart":295,"domainLookupEnd":295,"domainLookupStart":295,"fetchStart":295,"redirectEnd":0,"redirectStart":0,"requestStart":405.19999980926514,"responseEnd":520.0999999046326,"responseStart":422.69999980926514,"secureConnectionStart":295},{"duration":468.30000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/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&whisper-enabled=true","startTime":295.69999980926514,"connectEnd":295.69999980926514,"connectStart":295.69999980926514,"domainLookupEnd":295.69999980926514,"domainLookupStart":295.69999980926514,"fetchStart":295.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":405,"responseEnd":764,"responseStart":418.30000019073486,"secureConnectionStart":295.69999980926514},{"duration":122,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":295.90000009536743,"connectEnd":295.90000009536743,"connectStart":295.90000009536743,"domainLookupEnd":295.90000009536743,"domainLookupStart":295.90000009536743,"fetchStart":295.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":405.80000019073486,"responseEnd":417.90000009536743,"responseStart":416.69999980926514,"secureConnectionStart":295.90000009536743},{"duration":130.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":296.09999990463257,"connectEnd":296.09999990463257,"connectStart":296.09999990463257,"domainLookupEnd":296.09999990463257,"domainLookupStart":296.09999990463257,"fetchStart":296.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":408.69999980926514,"responseEnd":426.69999980926514,"responseStart":425.19999980926514,"secureConnectionStart":296.09999990463257},{"duration":131.7000002861023,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":296.19999980926514,"connectEnd":296.19999980926514,"connectStart":296.19999980926514,"domainLookupEnd":296.19999980926514,"domainLookupStart":296.19999980926514,"fetchStart":296.19999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":408.90000009536743,"responseEnd":427.90000009536743,"responseStart":426.90000009536743,"secureConnectionStart":296.19999980926514},{"duration":111.40000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":296.40000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":296.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":407.80000019073486,"responseStart":0,"secureConnectionStart":0},{"duration":139.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":296.59999990463257,"connectEnd":296.59999990463257,"connectStart":296.59999990463257,"domainLookupEnd":296.59999990463257,"domainLookupStart":296.59999990463257,"fetchStart":296.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":415.5,"responseEnd":436.19999980926514,"responseStart":434.69999980926514,"secureConnectionStart":296.59999990463257},{"duration":118.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/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":296.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":296.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":415.40000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":145.90000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/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,"connectEnd":297,"connectStart":297,"domainLookupEnd":297,"domainLookupStart":297,"fetchStart":297,"redirectEnd":0,"redirectStart":0,"requestStart":422.59999990463257,"responseEnd":442.90000009536743,"responseStart":436.80000019073486,"secureConnectionStart":297},{"duration":729.6000003814697,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":299.19999980926514,"connectEnd":299.19999980926514,"connectStart":299.19999980926514,"domainLookupEnd":299.19999980926514,"domainLookupStart":299.19999980926514,"fetchStart":299.19999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":1010.6999998092651,"responseEnd":1028.8000001907349,"responseStart":1027.0999999046326,"secureConnectionStart":299.19999980926514},{"duration":728.9000000953674,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":300.09999990463257,"connectEnd":300.09999990463257,"connectStart":300.09999990463257,"domainLookupEnd":300.09999990463257,"domainLookupStart":300.09999990463257,"fetchStart":300.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":1011,"responseEnd":1029,"responseStart":1028.3000001907349,"secureConnectionStart":300.09999990463257},{"duration":394.90000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":660.5,"connectEnd":660.5,"connectStart":660.5,"domainLookupEnd":660.5,"domainLookupStart":660.5,"fetchStart":660.5,"redirectEnd":0,"redirectStart":0,"requestStart":1011.0999999046326,"responseEnd":1055.4000000953674,"responseStart":1051.8000001907349,"secureConnectionStart":660.5}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":109,"responseStart":284,"responseEnd":299,"domLoading":288,"domInteractive":1428,"domContentLoadedEventStart":1428,"domContentLoadedEventEnd":1485,"domComplete":2393,"loadEventStart":2393,"loadEventEnd":2394,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1350.9000000953674},{"name":"bigPipe.sidebar-id.end","time":1351.6999998092651},{"name":"bigPipe.activity-panel-pipe-id.start","time":1352},{"name":"bigPipe.activity-panel-pipe-id.end","time":1353.1999998092651},{"name":"activityTabFullyLoaded","time":1501.6999998092651}],"measures":[],"correlationId":"55b38b2952c946","effectiveType":"4g","downlink":9.8,"rtt":0,"serverDuration":99,"dbReadsTimeInMs":15,"dbConnsTimeInMs":23,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Here is a backup dir before any attempts to run prepare:
ftp://ftp.askmonty.org/public/mdev18185-backup_before_prepare.tar.gz
It was stored from a different occurrence of the failure, but the error on prepare is the same, including the guilty file name:
/home/travis/server/10.4/bin/mariabackup based on MariaDB server 10.4.2-MariaDB Linux (x86_64)
mariabackup: cd to /home/travis/logs/vardir3/backup/
Removing ./test/t4.ibd
Renaming ./test/t4.new to ./test/t4.ibd
Removing ./test/seq10.ibd
Renaming ./test/seq10.new to ./test/seq10.ibd
Renaming ./test/#sql-6e62_10.new to ./test/#sql-6e62_10.ibd
ERROR : File ./test/seq5.ren was not found, but expected during rename processing
2019-01-09 16:19:22 0x7f137aeeb740 InnoDB: Assertion failure in file /data/src/10.4/extra/mariabackup/xtrabackup.cc line 5390
InnoDB: Failing assertion: 0
Corresponding backup/prepare logs: mdev18185-mbackup_backup.log
mdev18185-mbackup_prepare.log