10.4 30da40bb8c3
|
2019-01-09 22:15:09 0 [Note] InnoDB: Starting final batch to recover 2011 pages from redo log.
|
2019-01-09 22:15:09 0 [ERROR] [FATAL] InnoDB: Trying to read page number 96 in space 1239, space name test/t8#P#ver_pn, which is outside the tablespace bounds. Byte offset 0, len 16384
|
190109 22:15:09 [ERROR] mysqld got signal 6 ;
|
|
#4 0x00007fdd4b54d3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
|
#5 0x000055da0a61be66 in ib::fatal::~fatal (this=0x7fff327b27d0, __in_chrg=<optimized out>) at /data/src/10.4/storage/innobase/ut/ut0ut.cc:765
|
#6 0x000055da0a39c232 in fil_report_invalid_page_access (block_offset=96, space_id=1239, space_name=0x55da0d79b120 "test/t8#P#ver_pn", byte_offset=0, len=16384, is_read=true) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:4141
|
#7 0x000055da0a39ca5d in fil_io (type=..., sync=false, page_id=..., page_size=..., byte_offset=0, len=16384, buf=0x7fdd4695c000, message=0x7fdd4467aa98, ignore_missing_space=false) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:4287
|
#8 0x000055da0a34fbb5 in buf_read_page_low (err=0x7fff327b2f28, sync=false, type=64, mode=132, page_id=..., page_size=..., unzip=true, ignore_missing_space=false) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:181
|
#9 0x000055da0a351871 in buf_read_recv_pages (sync=false, space_id=1239, page_nos=0x7fff327b3110, n_stored=32) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:924
|
#10 0x000055da0a4adc6b in recv_read_in_area (page_id=...) at /data/src/10.4/storage/innobase/log/log0recv.cc:2001
|
#11 0x000055da0a4ae2d4 in recv_apply_hashed_log_recs (last_batch=true) at /data/src/10.4/storage/innobase/log/log0recv.cc:2106
|
#12 0x000055da0a5c4393 in srv_start (create_new_db=false) at /data/src/10.4/storage/innobase/srv/srv0start.cc:1861
|
#13 0x000055da09b62845 in innodb_init () at /data/src/10.4/extra/mariabackup/xtrabackup.cc:1988
|
#14 0x000055da09b6c9d8 in xtrabackup_prepare_func (argv=0x55da0cfd6a88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:5594
|
#15 0x000055da09b6ebda in main_low (argv=0x55da0cfd6a88) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6418
|
#16 0x000055da09b6e3ee in main (argc=7, argv=0x7fff327ba398) at /data/src/10.4/extra/mariabackup/xtrabackup.cc:6211
|
The log is attached as mbackup_prepare_1.log
Backup dirs before any attempts to prepare are stored here:
ftp://ftp.askmonty.org/public/mdev18194/
backup_0 is the initial full backup.
backup_1 is the incremental backup.
To reproduce, unpack the backups and run
bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=backup_0 --user=root
|
bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=backup_0 --incremental-dir=backup_1 --user=root
|
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 MariaBackupIncremental scenario:
github.com/MariaDB/randgen elenst-dev 0ebbe452a69, github.com/elenst/mariadb-toolbox master 6ded4b71568
|
perl ./runall-new.pl --basedir=/home/travis/server/10.4 --vardir=/home/travis/logs/vardir2 --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=MariaBackupIncremental --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
"--no-defaults" "--basedir=/home/travis/server/10.4" "--lc-messages-dir=/home/travis/server/10.4/share" "--character-sets-dir=/home/travis/server/10.4/share/charsets" "--tmpdir=/home/travis/logs/vardir2/tmp" "--core-file" "--datadir=/home/travis/logs/vardir2/data" "--max-allowed-packet=128Mb" "--port=19300" "--socket=/home/travis/logs/vardir2/mysql.sock" "--pid-file=/home/travis/logs/vardir2/mysql.pid" "--general-log" "--general-log-file=/home/travis/logs/vardir2/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 ~1 min, take the full backup from the running server:
bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_0 --protocol=tcp --port=19300 --user=root
|
(succeeded, the log attached as mbackup_backup_0.log
;
- after another ~1 minute, run the incremental backup as
bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_1 --incremental-basedir=/home/travis/logs/vardir2/backup_0 --protocol=tcp --port=19300 --user=root
|
(succeeded, the log attached as mbackup_backup_1.log
;
- after another ~1 minute, run the incremental backup again as
bin/mariabackup --backup --target-dir=/home/travis/logs/vardir2/backup_2 --incremental-basedir=/home/travis/logs/vardir2/backup_1 --protocol=tcp --port=19300 --user=root
|
(succeeded, the log attached as mbackup_backup_2.log
;
- let the test flow continue for a little while
- shut down the server gracefully (succeeded, the error log is attached as mysql.err_orig
;
- run mariabackup --prepare on the full backup as
bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=/home/travis/logs/vardir2/backup_0 --user=root
|
(succeeded, the log attached as mbackup_prepare_0.log
;
- run mariabackup --prepare on the first incremental backup as
bin/mariabackup --prepare --apply-log-only --innodb-file-io-threads=1 --target-dir=/home/travis/logs/vardir2/backup_0 --incremental-dir=/home/travis/logs/vardir2/backup_1 --user=root
|
(failed, the log is attached as mbackup_prepare_1.log
.
I have no information yet whether the problem happens on 10.1.
{"report":{"fcp":1268.5,"ttfb":327.39999985694885,"pageVisibility":"visible","entityId":71790,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"a37e81e8-91c3-4d71-bcbc-d9abd1dcfb64","navigationType":0,"readyForUser":1370.0999999046326,"redirectCount":0,"resourceLoadedEnd":1407.6999998092651,"resourceLoadedStart":332.7999999523163,"resourceTiming":[{"duration":261.89999985694885,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":332.7999999523163,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":332.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":594.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":261.90000009536743,"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":333.09999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":333.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":595,"responseStart":0,"secureConnectionStart":0},{"duration":270.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":333.2999999523163,"connectEnd":333.2999999523163,"connectStart":333.2999999523163,"domainLookupEnd":333.2999999523163,"domainLookupStart":333.2999999523163,"fetchStart":333.2999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":333.2999999523163,"responseEnd":603.8999998569489,"responseStart":603.8999998569489,"secureConnectionStart":333.2999999523163},{"duration":536.8999998569489,"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":333.5,"connectEnd":333.5,"connectStart":333.5,"domainLookupEnd":333.5,"domainLookupStart":333.5,"fetchStart":333.5,"redirectEnd":0,"redirectStart":0,"requestStart":333.5,"responseEnd":870.3999998569489,"responseStart":870.2999999523163,"secureConnectionStart":333.5},{"duration":540.5,"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":333.69999980926514,"connectEnd":333.69999980926514,"connectStart":333.69999980926514,"domainLookupEnd":333.69999980926514,"domainLookupStart":333.69999980926514,"fetchStart":333.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":333.69999980926514,"responseEnd":874.1999998092651,"responseStart":874.1999998092651,"secureConnectionStart":333.69999980926514},{"duration":540.7999999523163,"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":333.89999985694885,"connectEnd":333.89999985694885,"connectStart":333.89999985694885,"domainLookupEnd":333.89999985694885,"domainLookupStart":333.89999985694885,"fetchStart":333.89999985694885,"redirectEnd":0,"redirectStart":0,"requestStart":333.89999985694885,"responseEnd":874.6999998092651,"responseStart":874.5999999046326,"secureConnectionStart":333.89999985694885},{"duration":540.9000000953674,"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":334.09999990463257,"connectEnd":334.09999990463257,"connectStart":334.09999990463257,"domainLookupEnd":334.09999990463257,"domainLookupStart":334.09999990463257,"fetchStart":334.09999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":334.09999990463257,"responseEnd":875,"responseStart":875,"secureConnectionStart":334.09999990463257},{"duration":542,"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":334.19999980926514,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":334.19999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":876.1999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":541.1000001430511,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":334.39999985694885,"connectEnd":334.39999985694885,"connectStart":334.39999985694885,"domainLookupEnd":334.39999985694885,"domainLookupStart":334.39999985694885,"fetchStart":334.39999985694885,"redirectEnd":0,"redirectStart":0,"requestStart":334.39999985694885,"responseEnd":875.5,"responseStart":875.5,"secureConnectionStart":334.39999985694885},{"duration":542,"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":334.59999990463257,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":334.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":876.5999999046326,"responseStart":0,"secureConnectionStart":0},{"duration":541.3000001907349,"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":334.69999980926514,"connectEnd":334.69999980926514,"connectStart":334.69999980926514,"domainLookupEnd":334.69999980926514,"domainLookupStart":334.69999980926514,"fetchStart":334.69999980926514,"redirectEnd":0,"redirectStart":0,"requestStart":334.69999980926514,"responseEnd":876,"responseStart":876,"secureConnectionStart":334.69999980926514},{"duration":1025.1000001430511,"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":340.89999985694885,"connectEnd":340.89999985694885,"connectStart":340.89999985694885,"domainLookupEnd":340.89999985694885,"domainLookupStart":340.89999985694885,"fetchStart":340.89999985694885,"redirectEnd":0,"redirectStart":0,"requestStart":340.89999985694885,"responseEnd":1366,"responseStart":1366,"secureConnectionStart":340.89999985694885},{"duration":1012.7000000476837,"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":353.59999990463257,"connectEnd":353.59999990463257,"connectStart":353.59999990463257,"domainLookupEnd":353.59999990463257,"domainLookupStart":353.59999990463257,"fetchStart":353.59999990463257,"redirectEnd":0,"redirectStart":0,"requestStart":353.59999990463257,"responseEnd":1366.2999999523163,"responseStart":1366.2999999523163,"secureConnectionStart":353.59999990463257},{"duration":287.2999999523163,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":754.3999998569489,"connectEnd":754.3999998569489,"connectStart":754.3999998569489,"domainLookupEnd":754.3999998569489,"domainLookupStart":754.3999998569489,"fetchStart":754.3999998569489,"redirectEnd":0,"redirectStart":0,"requestStart":754.3999998569489,"responseEnd":1041.6999998092651,"responseStart":1041.6999998092651,"secureConnectionStart":754.3999998569489},{"duration":246,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2cib/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&whisper-enabled=true","startTime":1161.6999998092651,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":1161.6999998092651,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1407.6999998092651,"responseStart":0,"secureConnectionStart":0},{"duration":368.2999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/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&whisper-enabled=true","startTime":1162.7999999523163,"connectEnd":1162.7999999523163,"connectStart":1162.7999999523163,"domainLookupEnd":1162.7999999523163,"domainLookupStart":1162.7999999523163,"fetchStart":1162.7999999523163,"redirectEnd":0,"redirectStart":0,"requestStart":1162.7999999523163,"responseEnd":1531.0999999046326,"responseStart":1531.0999999046326,"secureConnectionStart":1162.7999999523163},{"duration":374.10000014305115,"initiatorType":"script","name":"https://jira.mariadb.org/s/097ae97cb8fbec7d6ea4bbb1f26955b9-CDN/lu2cib/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&whisper-enabled=true","startTime":1163.1999998092651,"connectEnd":1163.1999998092651,"connectStart":1163.1999998092651,"domainLookupEnd":1163.1999998092651,"domainLookupStart":1163.1999998092651,"fetchStart":1163.1999998092651,"redirectEnd":0,"redirectStart":0,"requestStart":1163.1999998092651,"responseEnd":1537.2999999523163,"responseStart":1537.2999999523163,"secureConnectionStart":1163.1999998092651}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":140,"responseStart":327,"responseEnd":353,"domLoading":331,"domInteractive":1464,"domContentLoadedEventStart":1464,"domContentLoadedEventEnd":1529,"domComplete":1916,"loadEventStart":1916,"loadEventEnd":1916,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1427.5},{"name":"bigPipe.sidebar-id.end","time":1428.2999999523163},{"name":"bigPipe.activity-panel-pipe-id.start","time":1428.5},{"name":"bigPipe.activity-panel-pipe-id.end","time":1433.0999999046326},{"name":"activityTabFullyLoaded","time":1551.5}],"measures":[],"correlationId":"379a90a08c1e60","effectiveType":"4g","downlink":10,"rtt":0,"serverDuration":113,"dbReadsTimeInMs":15,"dbConnsTimeInMs":23,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
I think that this should likely affect mariabackup 10.1 already. The code should be equivalent between 10.2, 10.3, and 10.4.