| Bug #115495 | "Unable to read page" crash on innodb.dblwr_encrypt_recover | ||
|---|---|---|---|
| Submitted: | 3 Jul 3:16 | Modified: | 17 Oct 12:03 |
| Reporter: | Laurynas Biveinis (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S6 (Debug Builds) |
| Version: | 8.4.3, 9.1.0 | OS: | MacOS (14.5) |
| Assigned to: | CPU Architecture: | ARM | |
[3 Jul 9:10]
MySQL Verification Team
Hello Laurynas, Thank you for the report and feedback. I quickly tried to reproduce this issue on OL7 but not seeing any issues. I assume this needs to be verified on MacOS. I'll get back to you if I need anything further on this. Thank you -- -- 8.4.1 scl enable devtoolset-11 bash MYSQL_VERSION="Bug115495" TARGET=/export/home/tmp/ushastry/src/$MYSQL_VERSION rm -rf /export/home/tmp/ushastry/src/$MYSQL_VERSION rm -rf bld/ mkdir bld && cd bld rm -rf CMakeCache.txt /home/umshastr/work/binaries/utils/cmake-3.28.1/bin/cmake .. -DCMAKE_INSTALL_PREFIX=$TARGET \ -DCMAKE_EXPORT_COMPILE_COMMANDS=ON \ -DCMAKE_BUILD_TYPE=Debug \ -DWITH_DEBUG=ON \ -DMYSQL_MAINTAINER_MODE=ON \ -DWITH_SYSTEM_LIBS=ON \ -DWITH_NDBCLUSTER_STORAGE_ENGINE=OFF \ -DFORCE_COLORED_OUTPUT=ON \ -DWITH_ZLIB=bundled \ -DWITH_ASAN=ON \ -DWITH_ASAN_SCOPE=ON \ -DWITH_UBSAN=ON \ -DWITH_PROTOBUF=bundled \ -DWITH_ICU=bundled make -j 16 make install - ./mtr innodb.dblwr_encrypt_recover Logging: ./mtr innodb.dblwr_encrypt_recover MySQL Version 8.4.1 Checking supported features - Binaries are debug compiled Using 'all' suites Collecting tests Removing old var directory Creating var directory '/export/home/tmp/ushastry/src/Bug115495/mysql-test/var' Installing system database Using parallel: 1 ============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ [ 50%] innodb.dblwr_encrypt_recover [ pass ] 16846 [100%] shutdown_report [ pass ] ------------------------------------------------------------------------------ The servers were restarted 0 times The servers were reinitialized 0 times Spent 16.846 of 54 seconds executing testcases Completed: All 2 tests were successful. regards, Umesh
[8 Jul 16:18]
MySQL Verification Team
Hello Laurynas, My apologies for the delay. I tried to reproduce on MacOS(14.5) with below options but still not able to reproduce. Am I missing here? Please let me know. Thank you. regards, Umesh ========= MYSQL_VERSION="Bug115495" TARGET=/Users/umshastr/Work/Src/$MYSQL_VERSION rm -rf /Users/umshastr/Work/Src/$MYSQL_VERSION rm -rf bld/ mkdir bld && cd bld rm -rf CMakeCache.txt cmake .. -DCMAKE_INSTALL_PREFIX=$TARGET -DCMAKE_EXPORT_COMPILE_COMMANDS=ON -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=ON -DMYSQL_MAINTAINER_MODE=ON -DWITH_SYSTEM_LIBS=ON -DWITH_NDBCLUSTER_STORAGE_ENGINE=OFF -DFORCE_COLORED_OUTPUT=ON -DWITH_ZLIB=bundled -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON -DWITH_ICU=bundled make -j 4 make install cd $TARGET/mysql-test cat ../docs/INFO_SRC commit: c96c4ce00c73c09b99cf29bc194bedf8c0b8d830 date: 2024-06-03 10:42:06 +0200 build-date: 2024-06-03 11:40:52 +0000 short: c96c4ce00c7 branch: mysql-8.4.1-release MySQL source 8.4.1 MySQL release maturity LTS ===== Compiler flags used: ===== CMAKE_BUILD_TYPE: Debug Compiler: AppleClang 15.0.0.15000309 COMPILE_DEFINITIONS: HAVE_CONFIG_H;__STDC_LIMIT_MACROS;__STDC_FORMAT_MACROS;_USE_MATH_DEFINES;LZ4_DISABLE_DEPRECATE_WARNINGS;HAVE_TLSv13 CMAKE_C_FLAGS: -fno-omit-frame-pointer -ftls-model=initial-exec -fsanitize=address -O1 -fno-inline -fsanitize-address-use-after-scope -fsanitize=undefined -O1 -fno-inline -Wall -Wextra -Wformat-security -Wvla -Wundef -Wmissing-format-attribute -Wwrite-strings -Wconditional-uninitialized -Wextra-semi -Wmissing-noreturn -Wunreachable-code-break -Wunreachable-code-return -Wstring-concatenation -Wdocumentation -Wno-documentation-deprecated-sync CMAKE_CXX_FLAGS: -std=c++20 -fno-omit-frame-pointer -ftls-model=initial-exec -fsanitize=address -O1 -fno-inline -fsanitize-address-use-after-scope -fsanitize=undefined -O1 -fno-inline -Wall -Wextra -Wformat-security -Wvla -Wundef -Wmissing-format-attribute -Woverloaded-virtual -Wcast-qual -Wno-null-conversion -Wno-unused-private-field -Wconditional-uninitialized -Wdeprecated -Wno-deprecated-declarations -Wno-shorten-64-to-32 -Wextra-semi -Wheader-hygiene -Wnon-virtual-dtor -Wundefined-reinterpret-cast -Wrange-loop-analysis -Winconsistent-missing-destructor-override -Winconsistent-missing-override -Wshadow-field -Wstring-concatenation -Wdocumentation -Wno-documentation-deprecated-sync CMAKE_C_FLAGS_DEBUG: -DSAFE_MUTEX -DENABLED_DEBUG_SYNC -g CMAKE_CXX_FLAGS_DEBUG: -DSAFE_MUTEX -DENABLED_DEBUG_SYNC -g ===== EOF ===== sw_vers ProductName: macOS ProductVersion: 14.5 BuildVersion: 23F79 -- Apple M1 Pro clang --version Apple clang version 15.0.0 (clang-1500.3.9.4) Target: arm64-apple-darwin23.5.0 Thread model: posix InstalledDir: /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin cmake --version cmake version 3.29.6 CMake suite maintained and supported by Kitware (kitware.com/cmake). ./mtr innodb.dblwr_encrypt_recover --debug-server Logging: ./mtr innodb.dblwr_encrypt_recover --debug-server MySQL Version 8.4.1 Checking supported features - Binaries are debug compiled Using 'all' suites Collecting tests Checking leftover processes Removing old var directory Creating var directory '/Users/umshastr/Work/Src/Bug115495/mysql-test/var' Installing system database Using parallel: 1 ============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ [ 50%] innodb.dblwr_encrypt_recover [ pass ] 8746 [100%] shutdown_report [ pass ] ------------------------------------------------------------------------------ The servers were restarted 0 times The servers were reinitialized 0 times Spent 8.746 of 25 seconds executing testcases Completed: All 2 tests were successful.
[8 Jul 16:33]
MySQL Verification Team
Pls ignore my earlier request :)
Finally, able to reproduce:
umshastr@umshastr-mac mysql-test % ./mtr innodb.dblwr_encrypt_recover --debug-server --repeat=10
Logging: ./mtr innodb.dblwr_encrypt_recover --debug-server --repeat=10
MySQL Version 8.4.1
Checking supported features
- Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/Users/umshastr/Work/Src/Bug115495/mysql-test/var'
Installing system database
Using parallel: 1
==============================================================================
TEST NAME RESULT TIME (ms) COMMENT
------------------------------------------------------------------------------
[ 9%] innodb.dblwr_encrypt_recover [ pass ] 8543
[ 18%] innodb.dblwr_encrypt_recover [ pass ] 10574
[ 27%] innodb.dblwr_encrypt_recover [ pass ] 10489
[ 36%] innodb.dblwr_encrypt_recover [ pass ] 10786
[ 45%] innodb.dblwr_encrypt_recover [ pass ] 8745
[ 54%] innodb.dblwr_encrypt_recover [ fail ]
Test ended at 2024-07-08 21:59:54
CURRENT_TEST: innodb.dblwr_encrypt_recover
mysqltest: At line 89: Query 'CHECK TABLE t1' failed.
ERROR 2013 (HY000): Lost connection to MySQL server during query
The result from queries just before the failure was:
# Find the on-disk page type of the given page.
SET @cmd = CONCAT('find_ondisk_page_type ', @space_id, ' ', @page_no);
SET SESSION innodb_interpreter = @cmd;
SELECT @@session.innodb_interpreter_output INTO @page_type;
SELECT @page_type;
@page_type
FIL_PAGE_ENCRYPTED
SET SESSION innodb_interpreter = 'find_tablespace_file_name test/t1';
SELECT @@session.innodb_interpreter_output INTO @space_file_name;
SET SESSION innodb_interpreter = 'find_tablespace_physical_page_size test/t1';
SELECT @@session.innodb_interpreter_output INTO @space_page_size;
SET SESSION innodb_interpreter = 'destroy';
# Kill the server
# Corrupt the root page of table t1 in the user tablespace.
SET SESSION innodb_interpreter = 'init';
SET SESSION innodb_interpreter = 'print_dblwr_has_encrypted_pages';
SET SESSION innodb_interpreter = 'destroy';
Pattern "Double write file has encrypted pages" found
Pattern "\[Note\] \[MY-\d+\] \[InnoDB\] Recovered page \[page id: space=\d+, page number=\d+\] from the doublewrite buffer" not found
CHECK TABLE t1;
safe_process[16476]: Child process: 16477, exit: 1
.
.
2024-07-08T16:29:54.623805Z 8 [ERROR] [MY-013183] [InnoDB] Assertion failure: buf0buf.cc:4064:ib::fatal triggered thread 0x171293000
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.4/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
2024-07-08T16:29:54Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x159407100
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...
stack_bottom = 171292e20 thread_stack 0x100000
0 mysqld 0x0000000105d39af8 my_print_stacktrace(unsigned char const*, unsigned long) + 236
1 mysqld 0x0000000102eb91b8 print_fatal_signal(int, __siginfo*) + 1252
2 mysqld 0x0000000102eb9ad0 my_server_abort() + 380
3 mysqld 0x0000000105d1a880 my_abort() + 20
4 mysqld 0x00000001074f4540 ut_dbg_assertion_failed(char const*, char const*, unsigned long long) + 1368
5 mysqld 0x000000010751d628 ib::fatal::~fatal() + 732
6 mysqld 0x000000010751d77c ib::fatal::~fatal() + 40
7 mysqld 0x00000001060bcff4 Buf_fetch<Buf_fetch_normal>::read_page() + 1092
8 mysqld 0x00000001060bbf54 Buf_fetch_normal::get(buf_block_t*&) + 612
9 mysqld 0x00000001060bf708 Buf_fetch<Buf_fetch_normal>::single_page() + 408
10 mysqld 0x00000001060bef98 buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, Page_fetch, ut::Location, mtr_t*, bool) + 1336
11 mysqld 0x0000000105ffdc18 btr_block_get_func(page_id_t const&, page_size_t const&, unsigned long, ut::Location, dict_index_t const*, mtr_t*) + 56
12 mysqld 0x0000000105fd95ec btr_root_block_get(dict_index_t const*, unsigned long, mtr_t*) + 344
13 mysqld 0x0000000105fda1b0 btr_root_get(dict_index_t const*, mtr_t*) + 20
14 mysqld 0x0000000105ff62b8 btr_validate_index(dict_index_t*, trx_t const*, bool) + 676
15 mysqld 0x00000001069fa0a8 ha_innobase::check(THD*, HA_CHECK_OPT*) + 3548
16 mysqld 0x00000001020616f8 mysql_admin_table(THD*, Table_ref*, HA_CHECK_OPT*, char const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, Table_ref*, HA_CHECK_OPT*), int (handler::*)(THD*, HA_CHECK_OPT*), int, Alter_info*, bool) + 12788
17 mysqld 0x000000010206f5e0 Sql_cmd_check_table::execute(THD*) + 1112
18 mysqld 0x0000000102501298 mysql_execute_command(THD*, bool) + 16844
19 mysqld 0x00000001024f4c3c dispatch_sql_command(THD*, Parser_state*) + 9504
20 mysqld 0x00000001024e2584 dispatch_command(THD*, COM_DATA const*, enum_server_command) + 30812
21 mysqld 0x00000001024ece9c do_command(THD*) + 5040
22 mysqld 0x0000000102e336ec handle_connection(void*) + 1132
23 mysqld 0x0000000107864d44 pfs_spawn_thread(void*) + 548
24 libsystem_pthread.dylib 0x000000019d956f94 _pthread_start + 136
25 libsystem_pthread.dylib 0x000000019d951d34 thread_start + 8
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (13799ac10): CHECK TABLE t1
Connection ID (thread ID): 8
Status: NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
safe_process[16492]: Child process: 16493, killed by signal: 6
----------SERVER LOG END-------------
[17 Oct 7:41]
Laurynas Biveinis
Same on 8.4.3
[17 Oct 12:03]
Laurynas Biveinis
Same on 9.1.0
Description: Intermittently, but on my machine, Debug + ASan + UBSan build reproduces it rather reliably: $ ./mtr innodb.dblwr_encrypt_recover ... [ 50%] innodb.dblwr_encrypt_recover [ fail ] Test ended at 2024-07-03 06:07:28 CURRENT_TEST: innodb.dblwr_encrypt_recover mysqltest: At line 89: Query 'CHECK TABLE t1' failed. ERROR 2013 (HY000): Lost connection to MySQL server during query ... 2024-07-03T03:07:22.975548Z 8 [ERROR] [MY-011906] [InnoDB] Database page corruption on disk or a failed file read of page [page id: space=6, page number=4]. You may have to recover from a backup. 2024-07-03T03:07:22.975596Z 8 [Note] [MY-011876] [InnoDB] Page dump in ascii and hex (16384 bytes): ... 2024-07-03T03:07:28.649521Z 8 [Note] [MY-011878] [InnoDB] Uncompressed page, stored checksum in field1 0, calculated checksums for field1: crc32 306581760/2851801011, innodb 1013711229, none 3735928559, stored checksum in field2 2684292629, calculated checksums for field2: crc32 306581760/2851801011, innodb 1371122432, none 3735928559, page LSN 0 0, low 4 bytes of LSN at page end 3702618360, page number (if stored to page already) 0, space id (if created with >= MySQL-4.1.1 and stored already) 0 InnoDB: Page may be a freshly allocated page 2024-07-03T03:07:28.649574Z 8 [Note] [MY-011907] [InnoDB] It is also possible that your operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption by dumping, dropping, and reimporting the corrupt table. You can use CHECK TABLE to scan your table for corruption. Please refer to http://dev.mysql.com/doc/refman/8.4/en/forcing-innodb-recovery.html for information about forcing recovery. 2024-07-03T03:07:28.649773Z 8 [ERROR] [MY-011899] [InnoDB] [FATAL] Unable to read page [page id: space=6, page number=4] into the buffer pool after 100 attempts. The most probable cause of this error may be that the table has been corrupted. Or, the table was compressed with with an algorithm that is not supported by this instance. If it is not a decompress failure, you can try to fix this problem by using innodb_force_recovery. Please see http://dev.mysql.com/doc/refman/8.4/en/ for more details. Aborting... 2024-07-03T03:07:28.649835Z 8 [ERROR] [MY-013183] [InnoDB] Assertion failure: buf0buf.cc:4064:ib::fatal triggered thread 0x16c973000 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to http://bugs.mysql.com. InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: http://dev.mysql.com/doc/refman/8.4/en/forcing-innodb-recovery.html InnoDB: about forcing recovery. 2024-07-03T03:07:28Z UTC - mysqld got signal 6 ; Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware. Thread pointer: 0x15f007100 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... stack_bottom = 16c972e20 thread_stack 0x100000 0 mysqld 0x000000010a6cb654 my_print_stacktrace(unsigned char const*, unsigned long) + 236 1 mysqld 0x000000010784e878 print_fatal_signal(int, __siginfo*) + 1252 2 mysqld 0x000000010784f190 my_server_abort() + 380 3 mysqld 0x000000010a6ac3dc my_abort() + 20 4 mysqld 0x000000010be8609c ut_dbg_assertion_failed(char const*, char const*, unsigned long long) + 1368 5 mysqld 0x000000010beaf184 ib::fatal::~fatal() + 732 6 mysqld 0x000000010beaf2d8 ib::fatal::~fatal() + 40 7 mysqld 0x000000010aa4eb50 Buf_fetch<Buf_fetch_normal>::read_page() + 1092 8 mysqld 0x000000010aa4dab0 Buf_fetch_normal::get(buf_block_t*&) + 612 9 mysqld 0x000000010aa51264 Buf_fetch<Buf_fetch_normal>::single_page() + 408 10 mysqld 0x000000010aa50af4 buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, Page_fetch, ut::Location, mtr_t*, bool) + 1336 11 mysqld 0x000000010a98f774 btr_block_get_func(page_id_t const&, page_size_t const&, unsigned long, ut::Location, dict_index_t const*, mtr_t*) + 56 12 mysqld 0x000000010a96b148 btr_root_block_get(dict_index_t const*, unsigned long, mtr_t*) + 344 13 mysqld 0x000000010a96bd0c btr_root_get(dict_index_t const*, mtr_t*) + 20 14 mysqld 0x000000010a987e14 btr_validate_index(dict_index_t*, trx_t const*, bool) + 676 15 mysqld 0x000000010b38bc04 ha_innobase::check(THD*, HA_CHECK_OPT*) + 3548 16 mysqld 0x00000001069f6db8 mysql_admin_table(THD*, Table_ref*, HA_CHECK_OPT*, char const*, thr_lock_type, bool, bool, unsigned int, int (*)(THD*, Table_ref*, HA_CHECK_OPT*), int (handler::*)(THD*, HA_CHECK_OPT*), int, Alter_info*, bool) + 12788 17 mysqld 0x0000000106a04ca0 Sql_cmd_check_table::execute(THD*) + 1112 18 mysqld 0x0000000106e96958 mysql_execute_command(THD*, bool) + 16844 19 mysqld 0x0000000106e8a2fc dispatch_sql_command(THD*, Parser_state*) + 9504 20 mysqld 0x0000000106e77c44 dispatch_command(THD*, COM_DATA const*, enum_server_command) + 30812 21 mysqld 0x0000000106e8255c do_command(THD*) + 5040 22 mysqld 0x00000001077c8dac handle_connection(void*) + 1132 23 mysqld 0x000000010c1f68a0 pfs_spawn_thread(void*) + 548 24 libsystem_pthread.dylib 0x000000018f3baf94 _pthread_start + 136 25 libsystem_pthread.dylib 0x000000018f3b5d34 thread_start + 8 Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (13d2999b0): CHECK TABLE t1 How to repeat: Server built with -DCMAKE_EXPORT_COMPILE_COMMANDS=ON -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=ON -DMYSQL_MAINTAINER_MODE=ON -DWITH_SYSTEM_LIBS=ON -DWITH_NDBCLUSTER_STORAGE_ENGINE=OFF -DFORCE_COLORED_OUTPUT=ON -DWITH_ZLIB=bundled -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON