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":941.7000002861023,"ttfb":276,"pageVisibility":"visible","entityId":71772,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"05c8d1a8-d4a8-4c9a-8326-11892c614d7e","navigationType":0,"readyForUser":1074.5,"redirectCount":0,"resourceLoadedEnd":681.3000001907349,"resourceLoadedStart":285.30000019073486,"resourceTiming":[{"duration":50.59999990463257,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":285.30000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":285.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":335.90000009536743,"responseStart":0,"secureConnectionStart":0},{"duration":50.5,"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":285.7000002861023,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":285.7000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":336.2000002861023,"responseStart":0,"secureConnectionStart":0},{"duration":258.30000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":285.90000009536743,"connectEnd":285.90000009536743,"connectStart":285.90000009536743,"domainLookupEnd":285.90000009536743,"domainLookupStart":285.90000009536743,"fetchStart":285.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":338.09999990463257,"responseEnd":544.2000002861023,"responseStart":356.09999990463257,"secureConnectionStart":285.90000009536743},{"duration":377.2999997138977,"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":286.7000002861023,"connectEnd":286.7000002861023,"connectStart":286.7000002861023,"domainLookupEnd":286.7000002861023,"domainLookupStart":286.7000002861023,"fetchStart":286.7000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":340.30000019073486,"responseEnd":664,"responseStart":367,"secureConnectionStart":286.7000002861023},{"duration":73.2000002861023,"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":287,"connectEnd":287,"connectStart":287,"domainLookupEnd":287,"domainLookupStart":287,"fetchStart":287,"redirectEnd":0,"redirectStart":0,"requestStart":341.5,"responseEnd":360.2000002861023,"responseStart":359,"secureConnectionStart":287},{"duration":75.09999990463257,"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":287.2000002861023,"connectEnd":287.2000002861023,"connectStart":287.2000002861023,"domainLookupEnd":287.2000002861023,"domainLookupStart":287.2000002861023,"fetchStart":287.2000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":342,"responseEnd":362.30000019073486,"responseStart":360.59999990463257,"secureConnectionStart":287.2000002861023},{"duration":75.5,"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":287.40000009536743,"connectEnd":287.40000009536743,"connectStart":287.40000009536743,"domainLookupEnd":287.40000009536743,"domainLookupStart":287.40000009536743,"fetchStart":287.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":343.59999990463257,"responseEnd":362.90000009536743,"responseStart":361.5,"secureConnectionStart":287.40000009536743},{"duration":54.700000286102295,"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":287.59999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":287.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":342.30000019073486,"responseStart":0,"secureConnectionStart":0},{"duration":77.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":287.7000002861023,"connectEnd":287.7000002861023,"connectStart":287.7000002861023,"domainLookupEnd":287.7000002861023,"domainLookupStart":287.7000002861023,"fetchStart":287.7000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":347.40000009536743,"responseEnd":365.30000019073486,"responseStart":363.90000009536743,"secureConnectionStart":287.7000002861023},{"duration":55.90000009536743,"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":287.90000009536743,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":287.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":343.80000019073486,"responseStart":0,"secureConnectionStart":0},{"duration":79.40000009536743,"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":288.09999990463257,"connectEnd":288.09999990463257,"connectStart":288.09999990463257,"domainLookupEnd":288.09999990463257,"domainLookupStart":288.09999990463257,"fetchStart":288.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":348.5,"responseEnd":367.5,"responseStart":365.7000002861023,"secureConnectionStart":288.09999990463257},{"duration":390.59999990463257,"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":290.5,"connectEnd":290.5,"connectStart":290.5,"domainLookupEnd":290.5,"domainLookupStart":290.5,"fetchStart":290.5,"redirectEnd":0,"redirectStart":0,"requestStart":398.90000009536743,"responseEnd":681.0999999046326,"responseStart":675.7000002861023,"secureConnectionStart":290.5},{"duration":390.59999990463257,"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":290.7000002861023,"connectEnd":290.7000002861023,"connectStart":290.7000002861023,"domainLookupEnd":290.7000002861023,"domainLookupStart":290.7000002861023,"fetchStart":290.7000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":399.2000002861023,"responseEnd":681.3000001907349,"responseStart":676.2000002861023,"secureConnectionStart":290.7000002861023},{"duration":81.40000009536743,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":697.3000001907349,"connectEnd":697.3000001907349,"connectStart":697.3000001907349,"domainLookupEnd":697.3000001907349,"domainLookupStart":697.3000001907349,"fetchStart":697.3000001907349,"redirectEnd":0,"redirectStart":0,"requestStart":746.3000001907349,"responseEnd":778.7000002861023,"responseStart":776.4000000953674,"secureConnectionStart":697.3000001907349},{"duration":186.59999990463257,"initiatorType":"script","name":"https://www.google-analytics.com/analytics.js","startTime":935.7000002861023,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":935.7000002861023,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1122.3000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":118.80000019073486,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":942,"connectEnd":942,"connectStart":942,"domainLookupEnd":942,"domainLookupStart":942,"fetchStart":942,"redirectEnd":0,"redirectStart":0,"requestStart":1023.5,"responseEnd":1060.8000001907349,"responseStart":1059.4000000953674,"secureConnectionStart":942}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":95,"responseStart":276,"responseEnd":286,"domLoading":279,"domInteractive":1158,"domContentLoadedEventStart":1158,"domContentLoadedEventEnd":1207,"domComplete":1478,"loadEventStart":1478,"loadEventEnd":1479,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1124.4000000953674},{"name":"bigPipe.sidebar-id.end","time":1125.3000001907349},{"name":"bigPipe.activity-panel-pipe-id.start","time":1125.4000000953674},{"name":"bigPipe.activity-panel-pipe-id.end","time":1126.7000002861023},{"name":"activityTabFullyLoaded","time":1227.0999999046326}],"measures":[],"correlationId":"55cd983a5d1f05","effectiveType":"4g","downlink":9.6,"rtt":0,"serverDuration":97,"dbReadsTimeInMs":10,"dbConnsTimeInMs":19,"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