[MDEV-27931] A page in innodb_checksum_algorithm=innodb is wrongly claimed to be corrupted Created: 2022-02-24  Updated: 2022-03-29  Resolved: 2022-03-28

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.2.0, 10.3.0, 10.4.0, 10.5.0, 10.6.0, 10.5.15, 10.6.7, 10.5
Fix Version/s: 10.2.44, 10.3.35, 10.4.25, 10.5.16, 10.6.8, 10.7.4, 10.8.3, 10.9.1

Type: Bug Priority: Critical
Reporter: Harvey Cooper Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File page1.bin    
Issue Links:
Problem/Incident
is caused by MDEV-19534 Make innodb_checksum_algorithm=full_c... Closed
Relates
relates to MDEV-28181 The innochecksum -w option was inadve... Closed
relates to MDEV-25105 Remove innodb_checksum_algorithm valu... Closed

 Description   

Hi, all MariaDB developers.

My team recently performed a successful MariaDB server upgrade, from 10.0.17 to 10.6.7.
The upgrade procedures is alike:

  • Prepare MariaDB 10.0.17 backup(previously it was backed up by xtrabackup 2.2.9)
    xtrabackup 2.2.9 backup data was totally good.
    dbchecksum for ibdata1 was totally good.
  • Copy prepared backup data into another VM.
  • Upgrade MariaDB to 10.6.7 (mysql_update was utilized) in that VM.

After a successful upgrade, we can verify that MariaDB 10.6.7 was good about the prepared data, no error log, business level sanity check was totally fine.

We haven't done CHECK TABLE because we set innodb_file_per_table=1 in my.cnf, ibdata1 should mostly be undo tablespace data(occupied around 200G in size), so I though running CHECK TABLE won't help either.

But when I run MariaDB 10.6.7 innodbchecksum for the ibdata1, it'll report page1 error. All data upgraded from 10.0.17 to 10.6.7 will report corruption.

The command I executed for backup the upgraded databased:
mariabackup --defaults-file=/etc/mysql/my.cnf --socket=/tmp/my.sock --user=xxxxx --password=xxxxxxxx --slave-info --backup --log-innodb-page-corruption --target-dir /tmp/tstempYF2mY9/prep_2022.02.24_093401.414814

Logs
(P.S. corrupt page content was excluded intentionally, it contain some sensitive data, if you need that, I may need to do some data redaction)

[01] 2022-02-24 09:34:01 Copying ibdata1 to /tmp/tstempYF2mY9/prep_2022.02.24_093401.414814/ibdata1
 
 
 
[01] 2022-02-24 09:40:52 Database page corruption detected at page 3994534, retrying...
 
 
 
[01] 2022-02-24 09:40:52 Database page corruption detected at page 3994534, retrying...
 
 
 
[01] 2022-02-24 09:40:52 Database page corruption detected at page 3994534, retrying...
 
 
 
[01] 2022-02-24 09:40:52 Database page corruption detected at page 3994534, retrying...
 
 
 
[01] 2022-02-24 09:40:54 Error: failed to read page after 10 retries. File ibdata1 seems to be corrupted. WARNING!!! The corruption is ignored due to log-innodb-page-corruption option, the backup can contain corrupted data.
 
 
 
2022-02-24 09:40:54 0x7f6663fff700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/extra/mariabackup/xtrabackup.cc line 804
 
 
 
InnoDB: Failing assertion: p
 
 
 
InnoDB: We intentionally generate a memory trap.
 
 
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
 
 
InnoDB: If you get repeated assertion failures or crashes, even
 
 
 
InnoDB: immediately after the mariadbd startup, there may be
 
 
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
 
 
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
 
 
InnoDB: about forcing recovery.
 
 
 
220224  9:40:54 [ERROR] mysqld got signal 6 ;
 
 
 
This could be because you hit a bug. It is also possible that this binary
 
 
 
or one of the libraries it was linked against is corrupt, improperly built,
 
 
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
 
 
diagnose the problem, but since we have already crashed,
 
 
 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.6.7-MariaDB
 
 
 
key_buffer_size=0
 
 
 
read_buffer_size=131072
 
 
 
max_used_connections=0
 
 
 
max_threads=1
 
 
 
thread_count=0
 
 
 
It is possible that mysqld could use up to
 
 
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6133 K  bytes of memory
 
 
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
 
 
Attempting backtrace. You can use the following information to find out
 
 
 
where mysqld died. If you see no messages after this, something went
 
 
 
terribly wrong...
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
stack_bottom = 0x0 thread_stack 0x49000
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274318)
 
 
 
addr2line: 'mariabackup': No such file
 
 
 
Printing to addr2line failed
 
 
 
mariabackup(my_print_stacktrace+0x2e)[0x55b01b984b7e]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442274971)
 
 
 
mariabackup(handle_fatal_signal+0x307)[0x55b01b3b6ef7]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442275535)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
sigaction.c:0(__restore_rt)[0x7f666d7d35f0]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)  
 
 
:0(__GI_raise)[0x7f666cc1f337]  
 
 
:0(__GI_abort)[0x7f666cc20a28]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)
 
 
 
addr2line: 'mariabackup': No such file
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276086)  
 
 
mariabackup(+0x6b3275)[0x55b01afd2275]
 
 
 
mariabackup(+0x6ff34a)[0x55b01b01e34a]        
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276829)
 
 
 
mariabackup(_ZN14CorruptedPages16add_page_no_lockEPKcmjb+0x10a)[0x55b01b02b1aa]
 
 
 
mariabackup(_ZN14CorruptedPages8add_pageEPKcmj+0x37)[0x55b01b02b247]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276829)
 
 
 
mariabackup(_Z15xb_fil_cur_readP12xb_fil_cur_tR14CorruptedPages+0x307)[0x55b01b0397a7]
 
 
 
mariabackup(+0x708b35)[0x55b01b027b35]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276829)
 
 
 
mariabackup(+0x708dcc)[0x55b01b027dcc]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442276829)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442277491)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442278246)
 
 
 
??:0(std::this_thread::__sleep_for(std::chrono::duration<long, std::ratio<1l, 1l> >, std::chrono::duration<long, std::ratio<1l, 1000000000l> >))[0x7f666d36e070]
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442278898)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442278898)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442279634)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442279634)
 
 
 
pthread_create.c:0(start_thread)[0x7f666d7cbe65] 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442279634)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
??:0(__clone)[0x7f666cce788d]
 
 
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
 
 
information that should help you find out what is causing the crash.
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442280417)
 
 
 
Writing a core file...
 
 
 
Working directory at /nutstore/mysql/db4
 
 
 
[00] 2022-02-24 09:40:54 >> log scanned up to (46654442281016)
 
 
 
Resource Limits:
 
 
 
Limit                     Soft Limit           Hard Limit           Units
 
 
 
Max cpu time              unlimited            unlimited            seconds   
 
 
Max file size             unlimited            unlimited            bytes
 
 
 
Max data size             unlimited            unlimited            bytes
 
 
 
Max stack size            8388608              unlimited            bytes
 
 
 
Max core file size        0                    unlimited            bytes
 
 
 
Max resident set          unlimited            unlimited            bytes
 
 
 
Max processes             4096                 1030594              processes
 
 
 
Max open files            1024                 4096                 files
 
 
 
Max locked memory         65536                65536                bytes
 
 
 
Max address space         unlimited            unlimited            bytes
 
 
 
Max file locks            unlimited            unlimited            locks
 
 
 
Max pending signals       1030594              1030594              signals
 
 
 
Max msgqueue size         819200               819200               bytes
 
 
 
Max nice priority         0                    0              
 
 
Max realtime priority     0                    0
 
 
 
Max realtime timeout      unlimited            unlimited            us
 
 
 
Core pattern: core

Since I add the --log-innodb-page-corruption cli option, I expect page corruption will be logged but not to halt the backup procedure, and after data preparing, the page corruption will be gone, since it happened in unallocated system table space?(need confirmation)

 Comments   
Comment by Marko Mäkelä [ 2022-02-24 ]

This bug is about page checksum validation. I would need a copy of a corrupted page to see what the cause of the problem might be.

Does innochecksum report checksum errors? If you rewrite the file to use innodb_checksum_algorithm=crc32 (using innochecksum), will backup then work?

Comment by Harvey Cooper [ 2022-02-24 ]

This bug is about page checksum validation. I would need a copy of a corrupted page to see what the cause of the problem might be.

Can I share it with you personally (for example, by email), because there are some sensitive data in it.

Does innochecksum report checksum errors? If you rewrite the file to use innodb_checksum_algorithm=crc32 (using innochecksum), will backup then work?

When I run 10.6.7 innochecksum, it'll report an error:
As if it happens at the beginning of the ibdata1 file? It there any potential compatibility problems when upgrading crc checksum?

$> innochecksum ibdata1
 
Variables (--variable-name=value)
 
and boolean options {FALSE|TRUE}  Value (after reading options)
 
--------------------------------- ----------------------------------------
 
verbose                           TRUE
 
count                             FALSE
 
start-page                        0
 
end-page                          0
 
page                              0
 
no-check                          FALSE
 
allow-mismatches                  0
 
page-type-summary                 FALSE
 
page-type-dump                    (No default value)
 
per-page-details                  FALSE
 
log                               (No default value)
 
leaf                              FALSE
 
merge                             0
 
Fail: page::1 invalid
 
Exceeded the maximum allowed checksum mismatch count::1 current::0

And there is a another log:
[01] 2022-02-24 09:40:53 Database page corruption detected at page 3994534, retrying...

When I run innochecksum -p 3994534 ibdata1, it will report the given page is ok.

$> innochecksum -p 3994534 ibdata1
 
Variables (--variable-name=value)
 
and boolean options {FALSE|TRUE}  Value (after reading options)
 
--------------------------------- ----------------------------------------
 
verbose                           TRUE
 
count                             FALSE
 
start-page                        3994534
 
end-page                          3994534
 
page                              3994534
 
no-check                          FALSE
 
allow-mismatches                  0
 
page-type-summary                 FALSE
 
page-type-dump                    (No default value)
 
per-page-details                  FALSE
 
log                               (No default value)
 
leaf                              FALSE
 
merge                             0

Comment by Marko Mäkelä [ 2022-02-24 ]

hcooper, thank you. You can extract the page contents with something like this:

dd bs=16384 skip=1 count=1 if=ibdata1 of=/tmp/page1.bin

The other page should be in a different data file if innochecksum did not complain about that. Unfortunately, the mariadb-backup error message does not identify the file name.

You can send them to my email. Page 1 is the change buffer bitmap page and it should not contain any user data.

Note: If you used innodb_checksum_algorithm=crc32 in the past on a big-endian processor on MariaDB Server 10.0 or 10.1 or MySQL 5.6, then this bug should occur due to MDEV-17958. You could confirm that by checking if the innochecksum from MariaDB 10.0 or 10.1 accepts the data files.

Comment by Harvey Cooper [ 2022-02-25 ]

dd bs=16384 skip=1 count=1 if=ibdata1 of=/tmp/page1.bin

You can send them to my email.

The page1.bin and the detailed logs had been sent to your email.

Note: If you used innodb_checksum_algorithm=crc32 in the past on a big-endian processor on MariaDB Server 10.0 or 10.1 or MySQL 5.6, then this bug should occur due to MDEV-17958. You could confirm that by checking if the innochecksum from MariaDB 10.0 or 10.1 accepts the data files.

I can confirm that our servers are always Intel-based CPU so it's always being little-endian.

Comment by Harvey Cooper [ 2022-02-28 ]

Hi, marko, have you received my email yet?

Comment by Harvey Cooper [ 2022-03-02 ]

Any update for this bug?

Comment by Marko Mäkelä [ 2022-03-25 ]

hcooper, sorry, I had overlooked this report. I don’t think that the page1.bin that you sent to me contains any application data, so I will attach it here. It is the first change buffer bitmap page in the system tablespace, covering pages 2 to 16383 in the system tablespace. A cursory look suggests that the page is fine. The 4 least significant bytes of FIL_PAGE_LSN (whose 4 most significant bytes start at offset 16) are duplicated at the end of the page. The 10.2 and 10.5 versions of innochecksum find that page to be valid. The 10.6 version of innochecksum says that it is invalid.

The first 10.6 commit with which the page is claimed invalid implemented MDEV-25105.

The hexdump from mariabackup seems to be for page 0x3cf3a6 in the system tablespace. It looks like an undo log page. That page was reported invalid also by the 10.5 innochecksum but not the 10.2 innochecksum. I will not attach that page to this report because it contains confidential data.

I created a dummy tablespace by doing the following:

perl -e 'print pack("H*","the 32768 hexadecimal digits")' > page.bin
 
dd bs=16384 count=1 seek=3994534 of=sparse.bin if=page.bin
 
innochecksum sparse.bin

Which values of innodb_checksum_algorithm have you used in the past?

In any case, I would recommend you to rebuild the data files from a logical dump, so that you would benefit from the more secure innodb_checksum_algorithm=full_crc32 format. If the data files were originally created before MySQL 5.1.48 or MariaDB 5.1.48, you could hit MDEV-27800.

Comment by Marko Mäkelä [ 2022-03-28 ]

The page page1.bin indeed carries a checksum of one of the implementations of innodb_checksum_algorithm=innodb. It was an intentional decision made in MDEV-25105 that such checksums will no longer be accepted by the innochecksum tool. It should still be accepted by the MariaDB server and mariadb-backup.

My intention was that the file could be converted to the slightly better innodb_checksum_algorithm=crc32 format by the following:

innochecksum -n -w ibdata1

Alas, in MDEV-25105 the -w option was accidentally removed altogether. With the following patch, it will work:

diff --git a/extra/innochecksum.cc b/extra/innochecksum.cc
 
index 6c732dbdb48..65224c8c3f5 100644
 
--- a/extra/innochecksum.cc
 
+++ b/extra/innochecksum.cc
 
@@ -1194,6 +1194,8 @@ static struct my_option innochecksum_options[] = {
 
   {"allow-mismatches", 'a', "Maximum checksum mismatch allowed.",
 
     &allow_mismatches, &allow_mismatches, 0,
 
     GET_ULL, REQUIRED_ARG, 0, 0, ULLONG_MAX, 0, 1, 0},
 
+  {"write", 'w', "Rewrite the checksum.",
 
+    &do_write, &do_write, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},
 
   {"page-type-summary", 'S', "Display a count of each page type "
 
    "in a tablespace.", &page_type_summary, &page_type_summary, 0,
 
    GET_BOOL, NO_ARG, 0, 0, 0, 0, 0, 0},

Converting the system tablespace to the full_crc32 format will require the database to be rebuilt.

I will check the other page shortly. That one is being rejected due to some earlier change somewhere between 10.2 and 10.5.

Comment by Harvey Cooper [ 2022-03-28 ]

@marko, thank you very much!

Although we solved this glitch by utilizing the mydumper to dump the whole db concurrently, and then load the db into MariaDB 10.6.

Comment by Harvey Cooper [ 2022-03-28 ]

Which values of innodb_checksum_algorithm have you used in the past?

We haven't set innodb_checksum_algorithm explicitly, according to https://mariadb.com/kb/en/innodb-system-variables/#innodb_checksum_algorithm, it should be innodb_checksum_algorithm=innodb in MariaDB 10.0.x

Comment by Marko Mäkelä [ 2022-03-28 ]

I tested the other page dump again. It is necessary to add one all-zero page before that page, so that page size will be correctly detected as 16384 bytes.

Such a 32768-byte file would be accepted by the 10.2, 10.3, and 10.4 versions of innochecksum by default, but no longer by the 10.5 version.
Each of those older-version innochecksum will reject the file when invoked as follows:

innochecksum -C crc32 sparse.bin

The 10.5 innochecksum would accept the file when invoked as follows:

innochecksum -C innodb sparse.bin

Starting with 10.5, the non-strict innodb_checksum_algorithm=crc32 validation is rejecting this page that appears to use innodb_checksum_algorithm=innodb.

Comment by Marko Mäkelä [ 2022-03-28 ]

The implementation of MDEV-19534 included the following change:

diff --git a/storage/innobase/buf/buf0checksum.cc b/storage/innobase/buf/buf0checksum.cc
 
index c5ad0cfb657..2fb97f3b137 100644
 
--- a/storage/innobase/buf/buf0checksum.cc
 
+++ b/storage/innobase/buf/buf0checksum.cc
 
@@ -33,11 +33,8 @@ Created Aug 11, 2011 Vasil Dimov
 
 #include "srv0srv.h"
 
 #endif /* !UNIV_INNOCHECKSUM */
 
 
-/** the macro MYSQL_SYSVAR_ENUM() requires "long unsigned int" and if we
 
-use srv_checksum_algorithm_t here then we get a compiler error:
 
-ha_innodb.cc:12251: error: cannot convert 'srv_checksum_algorithm_t*' to
 
-  'long unsigned int*' in initialization */
 
-ulong  srv_checksum_algorithm = SRV_CHECKSUM_ALGORITHM_INNODB;
 
+/** the value of innodb_checksum_algorithm */
 
+ulong  srv_checksum_algorithm;
 
 
 /** Calculate the CRC32 checksum of a page. The value is stored to the page
 
 when it is written to a file and also checked for a match when reading from

Due to this change, buf_page_is_corrupted() in innochecksum would invoke buf_calc_page_crc32(). Coincidentally, buf_calc_page_crc32() will return crc32=687675747 for this page, and that value happens to be the value of checksum_field2. Therefore, the following check will wrongly determine that the page is corrupted:

		if (crc32_inited
 
		    && ((checksum_field1 == crc32
 
			 && checksum_field2 != crc32)
 
			|| (checksum_field1 != crc32
 
			    && checksum_field2 == crc32))) {
 
			return true;
 
		}

I can repeat the wrong outcome also in the 10.4 innochecksum when applying the above patch.

The wrong claim of corrupted page in mariadb-backup --backup should be due to the same problem, but I have no easy way to check it.

Comment by Marko Mäkelä [ 2022-03-28 ]

The incorrect page validation should affect any MariaDB Server version since 10.0. After testing a fix on 10.4 and 10.5, I posted a fix for 10.2, so that this can be fixed in the last scheduled release before end-of-life.

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