[MDEV-24197] Prepare step of backup failing on large backup - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.2.27, 10.5.6, 10.5.9
Fix Version/s: 10.2.38, 10.3.29, 10.4.19, 10.5.10
Component/s: Backup
Labels:
None

Description

Customer is running backup on very large dataset (18TB). Backup completes successfully, but fails during prepare step.
Here is the planned backup process as the customer has detailed:

1. On Source:
  mariabackup --user=root --backup --target-dir=/opt/database/backup --stream=xbstream --parallel=12 | pigz -c | socat - TCP-LISTEN:4444,reuseaddr
2. On Target
  rm -rf /var/lib/mysql/*
  rm -rf /var/log/mysql/*
  cd /var/lib/mysql
  socat -u TCP:192.168.111.184:4444 STDOUT | pigz -dc | mbstream -x
  mariabackup --user=root --use-memory=100G --prepare --target-dir=/var/lib/mysql/
  rm -rf ib_logfile*
  chown -R mysql:mysql /var/lib/mysql/
  systemctl start mariadb

The prepare fails as such:
2020-11-03 15:08:46 0 [Note] InnoDB: To recover: 2407553 pages from log
2020-11-03 15:08:54 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=120831]
2020-11-03 15:08:54 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

screenshot-1.png
9 kB
2020-12-10 11:00

Issue Links

causes

MDEV-25328 --innodb command line option causes mariabackup to fail

Closed

is blocked by

MDEV-25031 Not applying INSERT_REUSE_REDUNDANT due to corruption on page

Closed

relates to

MDEV-17289 Multi-pass recovery fails to apply some redo log records

Closed

MDEV-21724 Optimize page_cur_insert_rec_low() redo logging

Closed

MDEV-24719 backport MDEV-24705 from 10.5 to 10.2, 10.3, 10.4

Closed

MDEV-25031 Not applying INSERT_REUSE_REDUNDANT due to corruption on page

Closed

MDEV-24705 add check that LSN of the last skipped log record equals to FIL_PAGE_LSN field

Closed

mentioned in: Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

(2 relates to, 6 mentioned in)

Activity

Ascending order - Click to sort in descending order

Isaac Venn (Inactive) added a comment - 2020-11-11 19:39

One important detail, database is using NFS as the data mount point.

Isaac Venn (Inactive) added a comment - 2020-11-11 19:39 One important detail, database is using NFS as the data mount point.

Isaac Venn (Inactive) added a comment - 2020-11-13 18:04

Output from execution:

[root@eod1-db180 ksizemore]# mariabackup --user=root --use-memory=100G --prepare --target-dir=/var/lib/mysql/
mariabackup based on MariaDB server 10.5.6-MariaDB Linux (x86_64)
[00] 2020-11-04 11:33:36 cd to /var/lib/mysql/
[00] 2020-11-04 11:33:37 Loading encryption plugin from file_key_management=file_key_management
[00] 2020-11-04 11:33:37 Loading encryption plugin
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--plugin_load=file_key_management=file_key_management'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_encryption_algorithm=aes_ctr'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_filekey=FILE:/etc/soteria/incognito/pf.txt'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_filename=/etc/soteria/incognito/kf.enc'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--innodb_encrypt_log=0'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--user=root'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--use-memory=100G'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--prepare'
[00] 2020-11-04 11:33:37 Encryption plugin parameter : '--target-dir=/var/lib/mysql/'
[00] 2020-11-04 11:33:37 This target seems to be not prepared yet.
[00] 2020-11-04 11:33:37 mariabackup: using the following InnoDB configuration for recovery:
[00] 2020-11-04 11:33:37 innodb_data_home_dir = .
[00] 2020-11-04 11:33:37 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2020-11-04 11:33:37 innodb_log_group_home_dir = .
[00] 2020-11-04 11:33:37 InnoDB: Using Linux native AIO
[00] 2020-11-04 11:33:37 Starting InnoDB instance for recovery.
[00] 2020-11-04 11:33:37 mariabackup: Using 107374182400 bytes for buffer pool (set by --use-memory parameter)
2020-11-04 11:33:37 0 [Note] InnoDB: Uses event mutexes
2020-11-04 11:33:37 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
2020-11-04 11:33:37 0 [Note] InnoDB: Number of pools: 1
2020-11-04 11:33:37 0 [Note] InnoDB: Using SSE4.2 crc32 instructions
2020-11-04 11:33:37 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 107374182400
2020-11-04 11:33:40 0 [Note] InnoDB: Completed initialization of buffer pool
2020-11-04 11:33:40 0 [Note] InnoDB: page_cleaner coordinator priority: -20
2020-11-04 11:33:40 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17798368931659
2020-11-04 11:33:55 0 [Note] InnoDB: Read redo log up to LSN=17800316136960
2020-11-04 11:34:10 0 [Note] InnoDB: Read redo log up to LSN=17802028461568
2020-11-04 11:34:25 0 [Note] InnoDB: Read redo log up to LSN=17803678723584
2020-11-04 11:34:40 0 [Note] InnoDB: Read redo log up to LSN=17805263187456
2020-11-04 11:34:55 0 [Note] InnoDB: Read redo log up to LSN=17806964502016
2020-11-04 11:35:10 0 [Note] InnoDB: Read redo log up to LSN=17808464555520
2020-11-04 11:35:25 0 [Note] InnoDB: Read redo log up to LSN=17810110819840
2020-11-04 11:35:40 0 [Note] InnoDB: Read redo log up to LSN=17811826421248
2020-11-04 11:35:55 0 [Note] InnoDB: Read redo log up to LSN=17813370580480
2020-11-04 11:36:10 0 [Note] InnoDB: Read redo log up to LSN=17814892654080
2020-11-04 11:36:25 0 [Note] InnoDB: Read redo log up to LSN=17816289553920
2020-11-04 11:36:40 0 [Note] InnoDB: Read redo log up to LSN=17817860189696
2020-11-04 11:36:55 0 [Note] InnoDB: Read redo log up to LSN=17819217505792
2020-11-04 11:37:06 0 [Note] InnoDB: Starting final batch to recover 1926332 pages from redo log.
2020-11-04 11:37:10 0 [Note] InnoDB: To recover: 1896528 pages from log
2020-11-04 11:37:25 0 [Note] InnoDB: To recover: 1761771 pages from log
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175]
2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-04 11:37:40 0 [Note] InnoDB: To recover: 1621249 pages from log
2020-11-04 11:37:55 0 [Note] InnoDB: To recover: 1582984 pages from log
2020-11-04 11:38:10 0 [Note] InnoDB: To recover: 1498736 pages from log
2020-11-04 11:38:25 0 [Note] InnoDB: To recover: 1472885 pages from log
2020-11-04 11:38:40 0 [Note] InnoDB: To recover: 1443488 pages from log
2020-11-04 11:38:55 0 [Note] InnoDB: To recover: 1407229 pages from log
2020-11-04 11:39:10 0 [Note] InnoDB: To recover: 1302578 pages from log
2020-11-04 11:39:25 0 [Note] InnoDB: To recover: 1268996 pages from log
2020-11-04 11:39:40 0 [Note] InnoDB: To recover: 1220566 pages from log
2020-11-04 11:39:55 0 [Note] InnoDB: To recover: 1190900 pages from log
2020-11-04 11:40:10 0 [Note] InnoDB: To recover: 1164636 pages from log
2020-11-04 11:40:25 0 [Note] InnoDB: To recover: 1148668 pages from log
2020-11-04 11:40:40 0 [Note] InnoDB: To recover: 1132183 pages from log
2020-11-04 11:40:55 0 [Note] InnoDB: To recover: 1115861 pages from log
2020-11-04 11:41:10 0 [Note] InnoDB: To recover: 1099438 pages from log
2020-11-04 11:41:25 0 [Note] InnoDB: To recover: 1079582 pages from log
2020-11-04 11:41:40 0 [Note] InnoDB: To recover: 1047383 pages from log
2020-11-04 11:41:55 0 [Note] InnoDB: To recover: 1016005 pages from log
2020-11-04 11:42:10 0 [Note] InnoDB: To recover: 1007048 pages from log
2020-11-04 11:42:25 0 [Note] InnoDB: To recover: 977827 pages from log
2020-11-04 11:42:40 0 [Note] InnoDB: To recover: 917880 pages from log
2020-11-04 11:42:55 0 [Note] InnoDB: To recover: 886759 pages from log
2020-11-04 11:43:10 0 [Note] InnoDB: To recover: 838145 pages from log
2020-11-04 11:43:25 0 [Note] InnoDB: To recover: 816488 pages from log
2020-11-04 11:43:40 0 [Note] InnoDB: To recover: 793531 pages from log
2020-11-04 11:43:55 0 [Note] InnoDB: To recover: 770551 pages from log
2020-11-04 11:44:10 0 [Note] InnoDB: To recover: 748032 pages from log
2020-11-04 11:44:25 0 [Note] InnoDB: To recover: 726293 pages from log
2020-11-04 11:44:40 0 [Note] InnoDB: To recover: 700586 pages from log
2020-11-04 11:44:55 0 [Note] InnoDB: To recover: 667151 pages from log
2020-11-04 11:45:10 0 [Note] InnoDB: To recover: 629661 pages from log
2020-11-04 11:45:36 0 [Note] InnoDB: To recover: 603933 pages from log
2020-11-04 11:46:18 0 [Note] InnoDB: To recover: 504587 pages from log
2020-11-04 11:46:33 0 [Note] InnoDB: To recover: 486258 pages from log
2020-11-04 11:46:48 0 [Note] InnoDB: To recover: 388853 pages from log
2020-11-04 11:47:03 0 [Note] InnoDB: To recover: 371831 pages from log
2020-11-04 11:47:18 0 [Note] InnoDB: To recover: 346568 pages from log
2020-11-04 11:47:33 0 [Note] InnoDB: To recover: 324923 pages from log
2020-11-04 11:47:48 0 [Note] InnoDB: To recover: 306987 pages from log
2020-11-04 11:48:03 0 [Note] InnoDB: To recover: 289274 pages from log
2020-11-04 11:48:18 0 [Note] InnoDB: To recover: 271332 pages from log
2020-11-04 11:48:33 0 [Note] InnoDB: To recover: 252692 pages from log
2020-11-04 11:48:48 0 [Note] InnoDB: To recover: 234123 pages from log
2020-11-04 11:49:03 0 [Note] InnoDB: To recover: 212071 pages from log
2020-11-04 11:49:18 0 [Note] InnoDB: To recover: 192106 pages from log
2020-11-04 11:49:33 0 [Note] InnoDB: To recover: 156859 pages from log
2020-11-04 11:49:48 0 [Note] InnoDB: To recover: 107376 pages from log
2020-11-04 11:50:03 0 [Note] InnoDB: To recover: 58700 pages from log
2020-11-04 11:50:06 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption
[00] FATAL ERROR: 2020-11-04 11:50:06 mariabackup: innodb_init() returned 39 (Data structure corruption).

Isaac Venn (Inactive) added a comment - 2020-11-13 18:04 Output from execution: [root@eod1-db180 ksizemore] # mariabackup --user=root --use-memory=100G --prepare --target-dir=/var/lib/mysql/ mariabackup based on MariaDB server 10.5.6-MariaDB Linux (x86_64) [00] 2020-11-04 11:33:36 cd to /var/lib/mysql/ [00] 2020-11-04 11:33:37 Loading encryption plugin from file_key_management=file_key_management [00] 2020-11-04 11:33:37 Loading encryption plugin [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--plugin_load=file_key_management=file_key_management' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_encryption_algorithm=aes_ctr' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_filekey=FILE:/etc/soteria/incognito/pf.txt' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--file_key_management_filename=/etc/soteria/incognito/kf.enc' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--innodb_encrypt_log=0' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--user=root' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--use-memory=100G' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--prepare' [00] 2020-11-04 11:33:37 Encryption plugin parameter : '--target-dir=/var/lib/mysql/' [00] 2020-11-04 11:33:37 This target seems to be not prepared yet. [00] 2020-11-04 11:33:37 mariabackup: using the following InnoDB configuration for recovery: [00] 2020-11-04 11:33:37 innodb_data_home_dir = . [00] 2020-11-04 11:33:37 innodb_data_file_path = ibdata1:12M:autoextend [00] 2020-11-04 11:33:37 innodb_log_group_home_dir = . [00] 2020-11-04 11:33:37 InnoDB: Using Linux native AIO [00] 2020-11-04 11:33:37 Starting InnoDB instance for recovery. [00] 2020-11-04 11:33:37 mariabackup: Using 107374182400 bytes for buffer pool (set by --use-memory parameter) 2020-11-04 11:33:37 0 [Note] InnoDB: Uses event mutexes 2020-11-04 11:33:37 0 [Note] InnoDB: Compressed tables use zlib 1.2.7 2020-11-04 11:33:37 0 [Note] InnoDB: Number of pools: 1 2020-11-04 11:33:37 0 [Note] InnoDB: Using SSE4.2 crc32 instructions 2020-11-04 11:33:37 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 107374182400 2020-11-04 11:33:40 0 [Note] InnoDB: Completed initialization of buffer pool 2020-11-04 11:33:40 0 [Note] InnoDB: page_cleaner coordinator priority: -20 2020-11-04 11:33:40 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17798368931659 2020-11-04 11:33:55 0 [Note] InnoDB: Read redo log up to LSN=17800316136960 2020-11-04 11:34:10 0 [Note] InnoDB: Read redo log up to LSN=17802028461568 2020-11-04 11:34:25 0 [Note] InnoDB: Read redo log up to LSN=17803678723584 2020-11-04 11:34:40 0 [Note] InnoDB: Read redo log up to LSN=17805263187456 2020-11-04 11:34:55 0 [Note] InnoDB: Read redo log up to LSN=17806964502016 2020-11-04 11:35:10 0 [Note] InnoDB: Read redo log up to LSN=17808464555520 2020-11-04 11:35:25 0 [Note] InnoDB: Read redo log up to LSN=17810110819840 2020-11-04 11:35:40 0 [Note] InnoDB: Read redo log up to LSN=17811826421248 2020-11-04 11:35:55 0 [Note] InnoDB: Read redo log up to LSN=17813370580480 2020-11-04 11:36:10 0 [Note] InnoDB: Read redo log up to LSN=17814892654080 2020-11-04 11:36:25 0 [Note] InnoDB: Read redo log up to LSN=17816289553920 2020-11-04 11:36:40 0 [Note] InnoDB: Read redo log up to LSN=17817860189696 2020-11-04 11:36:55 0 [Note] InnoDB: Read redo log up to LSN=17819217505792 2020-11-04 11:37:06 0 [Note] InnoDB: Starting final batch to recover 1926332 pages from redo log. 2020-11-04 11:37:10 0 [Note] InnoDB: To recover: 1896528 pages from log 2020-11-04 11:37:25 0 [Note] InnoDB: To recover: 1761771 pages from log 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:28 0 [ERROR] InnoDB: Not applying INSERT_HEAP_REDUNDANT due to corruption on [page id: space=0, page number=317175] 2020-11-04 11:37:28 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-04 11:37:40 0 [Note] InnoDB: To recover: 1621249 pages from log 2020-11-04 11:37:55 0 [Note] InnoDB: To recover: 1582984 pages from log 2020-11-04 11:38:10 0 [Note] InnoDB: To recover: 1498736 pages from log 2020-11-04 11:38:25 0 [Note] InnoDB: To recover: 1472885 pages from log 2020-11-04 11:38:40 0 [Note] InnoDB: To recover: 1443488 pages from log 2020-11-04 11:38:55 0 [Note] InnoDB: To recover: 1407229 pages from log 2020-11-04 11:39:10 0 [Note] InnoDB: To recover: 1302578 pages from log 2020-11-04 11:39:25 0 [Note] InnoDB: To recover: 1268996 pages from log 2020-11-04 11:39:40 0 [Note] InnoDB: To recover: 1220566 pages from log 2020-11-04 11:39:55 0 [Note] InnoDB: To recover: 1190900 pages from log 2020-11-04 11:40:10 0 [Note] InnoDB: To recover: 1164636 pages from log 2020-11-04 11:40:25 0 [Note] InnoDB: To recover: 1148668 pages from log 2020-11-04 11:40:40 0 [Note] InnoDB: To recover: 1132183 pages from log 2020-11-04 11:40:55 0 [Note] InnoDB: To recover: 1115861 pages from log 2020-11-04 11:41:10 0 [Note] InnoDB: To recover: 1099438 pages from log 2020-11-04 11:41:25 0 [Note] InnoDB: To recover: 1079582 pages from log 2020-11-04 11:41:40 0 [Note] InnoDB: To recover: 1047383 pages from log 2020-11-04 11:41:55 0 [Note] InnoDB: To recover: 1016005 pages from log 2020-11-04 11:42:10 0 [Note] InnoDB: To recover: 1007048 pages from log 2020-11-04 11:42:25 0 [Note] InnoDB: To recover: 977827 pages from log 2020-11-04 11:42:40 0 [Note] InnoDB: To recover: 917880 pages from log 2020-11-04 11:42:55 0 [Note] InnoDB: To recover: 886759 pages from log 2020-11-04 11:43:10 0 [Note] InnoDB: To recover: 838145 pages from log 2020-11-04 11:43:25 0 [Note] InnoDB: To recover: 816488 pages from log 2020-11-04 11:43:40 0 [Note] InnoDB: To recover: 793531 pages from log 2020-11-04 11:43:55 0 [Note] InnoDB: To recover: 770551 pages from log 2020-11-04 11:44:10 0 [Note] InnoDB: To recover: 748032 pages from log 2020-11-04 11:44:25 0 [Note] InnoDB: To recover: 726293 pages from log 2020-11-04 11:44:40 0 [Note] InnoDB: To recover: 700586 pages from log 2020-11-04 11:44:55 0 [Note] InnoDB: To recover: 667151 pages from log 2020-11-04 11:45:10 0 [Note] InnoDB: To recover: 629661 pages from log 2020-11-04 11:45:36 0 [Note] InnoDB: To recover: 603933 pages from log 2020-11-04 11:46:18 0 [Note] InnoDB: To recover: 504587 pages from log 2020-11-04 11:46:33 0 [Note] InnoDB: To recover: 486258 pages from log 2020-11-04 11:46:48 0 [Note] InnoDB: To recover: 388853 pages from log 2020-11-04 11:47:03 0 [Note] InnoDB: To recover: 371831 pages from log 2020-11-04 11:47:18 0 [Note] InnoDB: To recover: 346568 pages from log 2020-11-04 11:47:33 0 [Note] InnoDB: To recover: 324923 pages from log 2020-11-04 11:47:48 0 [Note] InnoDB: To recover: 306987 pages from log 2020-11-04 11:48:03 0 [Note] InnoDB: To recover: 289274 pages from log 2020-11-04 11:48:18 0 [Note] InnoDB: To recover: 271332 pages from log 2020-11-04 11:48:33 0 [Note] InnoDB: To recover: 252692 pages from log 2020-11-04 11:48:48 0 [Note] InnoDB: To recover: 234123 pages from log 2020-11-04 11:49:03 0 [Note] InnoDB: To recover: 212071 pages from log 2020-11-04 11:49:18 0 [Note] InnoDB: To recover: 192106 pages from log 2020-11-04 11:49:33 0 [Note] InnoDB: To recover: 156859 pages from log 2020-11-04 11:49:48 0 [Note] InnoDB: To recover: 107376 pages from log 2020-11-04 11:50:03 0 [Note] InnoDB: To recover: 58700 pages from log 2020-11-04 11:50:06 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption [00] FATAL ERROR: 2020-11-04 11:50:06 mariabackup: innodb_init() returned 39 (Data structure corruption).

derek labian added a comment - 2020-11-16 18:35

I am also having a similar issue.

I have two servers in an active-active replication configuration running 5.6. They had been online for about 45 days. Replication hung and I was unable to stop replication or shutdown the server. I ended up killing the process and on restart, the recovery failed with these same errors. This was not critical data for us so I decided I would re-sync from the master. I removed the dataset and prepared a backup with MariaDB Backup. To my surprise, when I tried to prepare the backup, I ran into the same issues after the crash. There seems to be something 5.6+ feels is corrupted with these datasets. I also upgraded to 5.8 on the restoration server, however the backup server is still 5.6.

My dataset is small compared to the OP, only 377GB.

mariabackup --prepare --target-dir=/datastore2/backup/
/datastore1/daemon/mysql/bin/mariabackup based on MariaDB server 10.5.8-MariaDB Linux (x86_64)
[00] 2020-11-16 18:26:12 cd to /datastore2/backup/
[00] 2020-11-16 18:26:12 This target seems to be not prepared yet.
[00] 2020-11-16 18:26:12 mariabackup: using the following InnoDB configuration for recovery:
[00] 2020-11-16 18:26:12 innodb_data_home_dir = .
[00] 2020-11-16 18:26:12 innodb_data_file_path = ibdata1:50G:autoextend
[00] 2020-11-16 18:26:12 innodb_log_group_home_dir = .
[00] 2020-11-16 18:26:12 InnoDB: Using Linux native AIO
[00] 2020-11-16 18:26:12 Starting InnoDB instance for recovery.
[00] 2020-11-16 18:26:12 mariabackup: Using 107374182400 bytes for buffer pool (set by --use-memory parameter)
2020-11-16 18:26:12 0 [Note] InnoDB: Uses event mutexes
2020-11-16 18:26:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-11-16 18:26:12 0 [Note] InnoDB: Number of pools: 1
2020-11-16 18:26:12 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
/datastore1/daemon/mysql/bin/mariabackup: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-11-16 18:26:12 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 107374182400
2020-11-16 18:26:15 0 [Note] InnoDB: Completed initialization of buffer pool
2020-11-16 18:26:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8678346070289,8678346070289
2020-11-16 18:26:20 0 [Note] InnoDB: Starting final batch to recover 114168 pages from redo log.
2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=5263]
2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=51008]
2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=51008]
2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-16 18:26:22 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption
[00] FATAL ERROR: 2020-11-16 18:26:22 mariabackup: innodb_init() returned 39 (Data structure corruption).

The segment where these errors actually occur, there's no additional info:

2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678353152431: [page id: space=0, page number=9735]
2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678347254254: [page id: space=0, page number=29824]
2020-11-16 18:04:51 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=8763]
2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678349440356: [page id: space=0, page number=9729]
2020-11-16 18:04:51 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678354972951: [page id: space=0, page number=9766]
2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678346642997: [page id: space=0, page number=8763]
2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678353152924: [page id: space=0, page number=9735]

derek labian added a comment - 2020-11-16 18:35 I am also having a similar issue. I have two servers in an active-active replication configuration running 5.6. They had been online for about 45 days. Replication hung and I was unable to stop replication or shutdown the server. I ended up killing the process and on restart, the recovery failed with these same errors. This was not critical data for us so I decided I would re-sync from the master. I removed the dataset and prepared a backup with MariaDB Backup. To my surprise, when I tried to prepare the backup, I ran into the same issues after the crash. There seems to be something 5.6+ feels is corrupted with these datasets. I also upgraded to 5.8 on the restoration server, however the backup server is still 5.6. My dataset is small compared to the OP, only 377GB. mariabackup --prepare --target-dir=/datastore2/backup/ /datastore1/daemon/mysql/bin/mariabackup based on MariaDB server 10.5.8-MariaDB Linux (x86_64) [00] 2020-11-16 18:26:12 cd to /datastore2/backup/ [00] 2020-11-16 18:26:12 This target seems to be not prepared yet. [00] 2020-11-16 18:26:12 mariabackup: using the following InnoDB configuration for recovery: [00] 2020-11-16 18:26:12 innodb_data_home_dir = . [00] 2020-11-16 18:26:12 innodb_data_file_path = ibdata1:50G:autoextend [00] 2020-11-16 18:26:12 innodb_log_group_home_dir = . [00] 2020-11-16 18:26:12 InnoDB: Using Linux native AIO [00] 2020-11-16 18:26:12 Starting InnoDB instance for recovery. [00] 2020-11-16 18:26:12 mariabackup: Using 107374182400 bytes for buffer pool (set by --use-memory parameter) 2020-11-16 18:26:12 0 [Note] InnoDB: Uses event mutexes 2020-11-16 18:26:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2020-11-16 18:26:12 0 [Note] InnoDB: Number of pools: 1 2020-11-16 18:26:12 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions /datastore1/daemon/mysql/bin/mariabackup: O_TMPFILE is not supported on /tmp (disabling future attempts) 2020-11-16 18:26:12 0 [Note] InnoDB: Initializing buffer pool, total size = 107374182400, chunk size = 107374182400 2020-11-16 18:26:15 0 [Note] InnoDB: Completed initialization of buffer pool 2020-11-16 18:26:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=8678346070289,8678346070289 2020-11-16 18:26:20 0 [Note] InnoDB: Starting final batch to recover 114168 pages from redo log. 2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=5263] 2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=51008] 2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-16 18:26:20 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=51008] 2020-11-16 18:26:20 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-16 18:26:22 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption [00] FATAL ERROR: 2020-11-16 18:26:22 mariabackup: innodb_init() returned 39 (Data structure corruption). The segment where these errors actually occur, there's no additional info: 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678353152431: [page id: space=0, page number=9735] 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678347254254: [page id: space=0, page number=29824] 2020-11-16 18:04:51 0 [ERROR] InnoDB: Not applying INSERT_REUSE_REDUNDANT due to corruption on [page id: space=0, page number=8763] 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678349440356: [page id: space=0, page number=9729] 2020-11-16 18:04:51 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption. 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678354972951: [page id: space=0, page number=9766] 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678346642997: [page id: space=0, page number=8763] 2020-11-16 18:04:51 0 [Note] InnoDB: apply 8678353152924: [page id: space=0, page number=9735]

Vladislav Lesin added a comment - 2020-11-18 13:15 - edited

The error itself is issued from page_apply_insert_redundant(), which is called after page corruption check. So the page is not corrupted as it passed the check, that is why backup was finished successfully. According to the page_apply_insert_redundant() there can be several reasons of the error, so I modified this function to determine what exactly reason caused the error message, and created custom build request: TODO-2645. Please ask the customer to run "mariabackup --prepare" with "--dbug=d,ib_log" option, and then send mariabackup log to us.

Vladislav Lesin added a comment - 2020-11-18 13:15 - edited The error itself is issued from page_apply_insert_redundant(), which is called after page corruption check. So the page is not corrupted as it passed the check, that is why backup was finished successfully. According to the page_apply_insert_redundant() there can be several reasons of the error, so I modified this function to determine what exactly reason caused the error message, and created custom build request: TODO-2645. Please ask the customer to run "mariabackup --prepare" with "--dbug=d,ib_log" option, and then send mariabackup log to us.

Marko Mäkelä added a comment - 2020-11-19 05:45

I believe that the cause of this is that the write-ahead logging constraints were broken at some point of the chain. In ~~MDEV-17289~~ we had something very similar to this. The way how inserts of records into index pages are logged and applied was rewritten in ~~MDEV-21724~~. It is possible that the more thorough consistency checks that were implemented in ~~MDEV-21724~~ allow to catch such corruption in a few more cases. Before that rewrite, we might allow recovery to proceed and might hit a hard-to-reproduce problem later.

I believe that implementing ~~MDEV-18976~~ would make recovery more robust, by allowing even better consistency checks. If that measure is implemented, recovery should be able to notice that a page image is not in sync with the log record, or that some log record was missed during recovery.

Note: The move to more physical redo log format in ~~MDEV-12353~~ removed some opportunity to perform consistency checks. But, even with the old implementation, I think that by far, the best chances to notice such inconsistency was when trying to apply an insert operation. The inconsistency typically led to the server crashing (repeatedly). With the new ~~MDEV-12353~~/~~MDEV-21724~~ log format, we are reporting an error and avoiding a crash. (OK, until ~~MDEV-13542~~ is fixed, we may crash when the corrupted table is accessed.)

Marko Mäkelä added a comment - 2020-11-19 05:45 I believe that the cause of this is that the write-ahead logging constraints were broken at some point of the chain. In MDEV-17289 we had something very similar to this. The way how inserts of records into index pages are logged and applied was rewritten in MDEV-21724 . It is possible that the more thorough consistency checks that were implemented in MDEV-21724 allow to catch such corruption in a few more cases. Before that rewrite, we might allow recovery to proceed and might hit a hard-to-reproduce problem later. I believe that implementing MDEV-18976 would make recovery more robust, by allowing even better consistency checks. If that measure is implemented, recovery should be able to notice that a page image is not in sync with the log record, or that some log record was missed during recovery. Note: The move to more physical redo log format in MDEV-12353 removed some opportunity to perform consistency checks. But, even with the old implementation, I think that by far, the best chances to notice such inconsistency was when trying to apply an insert operation. The inconsistency typically led to the server crashing (repeatedly). With the new MDEV-12353 / MDEV-21724 log format, we are reporting an error and avoiding a crash. (OK, until MDEV-13542 is fixed, we may crash when the corrupted table is accessed.)

Todd Coker added a comment - 2020-12-02 20:01

The customer's consultant has tried preparing again using the debug build. Output is attached to case CS0154009. There's a bit more information about the generic error.

2020-12-02  0:08:37 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error

[00] FATAL ERROR: 2020-12-02 00:08:37 mariabackup: innodb_init() returned 11 (Generic error).

Todd Coker added a comment - 2020-12-02 20:01 The customer's consultant has tried preparing again using the debug build. Output is attached to case CS0154009. There's a bit more information about the generic error. 2020-12-02 0:08:37 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1537] with error Generic error [00] FATAL ERROR: 2020-12-02 00:08:37 mariabackup: innodb_init() returned 11 (Generic error).

Richard added a comment - 2020-12-10 11:02

I have hit the same error on 10.5.8

The option "Set innodb_force_recovery=1 to ignore corruption." sounds risky.

Can anyone suggest a workaround?

Thanks

Richard added a comment - 2020-12-10 11:02 Hi I have hit the same error on 10.5.8 The option "Set innodb_force_recovery=1 to ignore corruption." sounds risky. Can anyone suggest a workaround? Thanks

Marko Mäkelä added a comment - 2021-03-11 12:50

For 10.5, this could have been fixed by ~~MDEV-25031~~, which fixed a regression that was introduced in 10.5.
For 10.2.27, I have no idea of the cause.

Marko Mäkelä added a comment - 2021-03-11 12:50 For 10.5, this could have been fixed by MDEV-25031 , which fixed a regression that was introduced in 10.5. For 10.2.27, I have no idea of the cause.

Marko Mäkelä added a comment - 2021-03-29 08:12

Pull request #1772 would implement innodb_force_recovery=1 for mariabackup --prepare, and I think solve this issue.

Marko Mäkelä added a comment - 2021-03-29 08:12 Pull request #1772 would implement innodb_force_recovery=1 for mariabackup --prepare , and I think solve this issue.

Marko Mäkelä added a comment - 2021-04-01 10:38

The contributed fix is basically only a work-around: it allows the option --innodb-force-recovery=1 to be specified when applying logs (preparing a backup).

The root cause of the failure is always something else (such as ~~MDEV-25031~~ for the case that is in the Description). This work-around allows an attempt to restore a backup even if some corruption is present.

Marko Mäkelä added a comment - 2021-04-01 10:38 The contributed fix is basically only a work-around: it allows the option --innodb-force-recovery=1 to be specified when applying logs (preparing a backup). The root cause of the failure is always something else (such as MDEV-25031 for the case that is in the Description). This work-around allows an attempt to restore a backup even if some corruption is present.

Rick Pizzi (Inactive) added a comment - 2021-04-01 11:51

marko will the backup still be consistent when restoring with force-recovery=1? especially regarding the position resp. the master (in case we want to make this server a replica)?

Rick Pizzi (Inactive) added a comment - 2021-04-01 11:51 marko will the backup still be consistent when restoring with force-recovery=1? especially regarding the position resp. the master (in case we want to make this server a replica)?

Marko Mäkelä added a comment - 2021-08-20 09:35

The purpose of innodb_force_recovery=1 is to ignore some errors (corrupted pages or missing data files). Depending on where the errors occur, it may or may not be safe. In the general case, I would not recommend to continue using a server where recovery errors had been ignored in the past.

When it comes to MariaDB Server (not Mariabackup), it would be nice if there was a way to set innodb_force_recovery to the values 2 or 3 in such a way that the recovery will run in strict mode. If no crash recovery is involved, those values of the parameter are not expected to cause further corruption. The main purpose of innodb_force_recovery is to allow data to be extracted from a corrupted database.

Marko Mäkelä added a comment - 2021-08-20 09:35 The purpose of innodb_force_recovery=1 is to ignore some errors (corrupted pages or missing data files). Depending on where the errors occur, it may or may not be safe. In the general case, I would not recommend to continue using a server where recovery errors had been ignored in the past. When it comes to MariaDB Server (not Mariabackup), it would be nice if there was a way to set innodb_force_recovery to the values 2 or 3 in such a way that the recovery will run in strict mode. If no crash recovery is involved, those values of the parameter are not expected to cause further corruption. The main purpose of innodb_force_recovery is to allow data to be extracted from a corrupted database.

People

Assignee:: Marko Mäkelä

Reporter:: Isaac Venn (Inactive)

Votes:: 7 Vote for this issue

Watchers:: 18 Start watching this issue

Dates

Created:: 2020-11-11 19:38

Updated:: 2024-09-06 10:00

Resolved:: 2021-04-01 10:38

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.