[MDEV-24197] Prepare step of backup failing on large backup Created: 2020-11-11  Updated: 2023-10-31  Resolved: 2021-04-01

Status: Closed
Project: MariaDB Server
Component/s: Backup
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

Type: Bug Priority: Critical
Reporter: Isaac Venn (Inactive) Assignee: Marko Mäkelä
Resolution: Fixed Votes: 7
Labels: None

Attachments: PNG File screenshot-1.png    
Issue Links:
Blocks
is blocked by MDEV-25031 Not applying INSERT_REUSE_REDUNDANT d... Closed
Problem/Incident
causes MDEV-25328 --innodb command line option causes m... Closed
Relates
relates to MDEV-17289 Multi-pass recovery fails to apply so... Closed
relates to MDEV-21724 Optimize page_cur_insert_rec_low() re... Closed
relates to MDEV-24719 backport MDEV-24705 from 10.5 to 10.2... Closed
relates to MDEV-25031 Not applying INSERT_REUSE_REDUNDANT d... Closed
relates to MDEV-24705 add check that LSN of the last skippe... Closed

 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.

 Comments   
Comment by Isaac Venn (Inactive) [ 2020-11-11 ]

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

Comment by Isaac Venn (Inactive) [ 2020-11-13 ]

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).

Comment by derek labian [ 2020-11-16 ]

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]

Comment by Vladislav Lesin [ 2020-11-18 ]

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.

Comment by Marko Mäkelä [ 2020-11-19 ]

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.)

Comment by Todd Coker (Inactive) [ 2020-12-02 ]

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).

Comment by Richard [ 2020-12-10 ]

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

Comment by Marko Mäkelä [ 2021-03-11 ]

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.

Comment by Marko Mäkelä [ 2021-03-29 ]

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

Comment by Marko Mäkelä [ 2021-04-01 ]

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.

Comment by Rick Pizzi [ 2021-04-01 ]

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)?

Comment by Marko Mäkelä [ 2021-08-20 ]

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.

Generated at Thu Feb 08 09:28:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.