[MDEV-18610] yum安装mariadb server后，使用mysql_install_db进行初始化完成，启动报如下错误 Created: 2019-02-18  Updated: 2019-03-20  Resolved: 2019-03-20

Status: Closed
Project: MariaDB Server
Component/s: Admin statements
Affects Version/s: 10.2.22
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: lei Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: innodb, need_feedback
Environment:

centos7.4

Issue Links:
Relates
relates to MDEV-18639 Assertion failure upon attempt to sta... Closed

 Description   

2019-02-15 11:39:49 140588899317888 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:39:49 140588899317888 [Warning] InnoDB: Using innodb_file_format_max is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:39:50 140587836704512 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
2019-02-15 11:40:08 140019898890368 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:40:08 140019898890368 [Warning] InnoDB: Using innodb_file_format_max is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Uses event mutexes
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Compressed tables use zlib 1.2.7
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Using Linux native AIO
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Number of pools: 1
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Using SSE2 crc32 instructions
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Initializing buffer pool, total size = 512M, instances = 1, chunk size = 128M
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Completed initialization of buffer pool
2019-02-15 11:40:08 140017514465024 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Opened 8 undo tablespaces
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Highest supported file format is Barracuda.
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Starting crash recovery from checkpoint LSN=56530
2019-02-15 11:40:08 140019898890368 [ERROR] InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE for redo log record 1 (page 1:0) at 56539.
2019-02-15 11:40:08 140019898890368 [ERROR] InnoDB: ############### CORRUPT LOG RECORD FOUND ##################
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Log record type 1, page 1:0. Log parsing proceeded successfully up to 56539. Previous log record type 31, is multi 1 Recv offset 9, prev 11764
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Hex dump starting 9 bytes before and ending 100 bytes after the corrupted record:
len 109; hex 38000000000000dcd201010000ae80ea040100003a033b01020201020018030801020032000000000008010200f2000000000008010201b20000000000080102027200000000000801020332000000000008010203f2000000000008010204b200000000000801020572000000; asc 8 : ; 2 r 2 r ;
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Set innodb_force_recovery to ignore this error.
2019-02-15 11:40:08 140019898890368 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2019-02-15 11:40:08 140019898890368 [Note] InnoDB: Starting shutdown...
2019-02-15 11:40:09 0x7f58ec55b880 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.22/storage/innobase/fil/fil0fil.cc line 746
InnoDB: Failing assertion: UT_LIST_GET_LEN(fil_system->LRU) > 0
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 mysqld 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.
190215 11:40:09 [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.2.22-MariaDB-log
key_buffer_size=8388608
read_buffer_size=2097152
max_used_connections=0
max_threads=3002
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 12368366 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...
stack_bottom = 0x0 thread_stack 0x49000
mysqld(my_print_stacktrace+0x2e)[0x557a8917ad6e]
mysqld(handle_fatal_signal+0x355)[0x557a88bfc665]
addr2line: 'mysqld': No such file
sigaction.c:0(__restore_rt)[0x7f58ec16a5e0]
:0(__GI_raise)[0x7f58ea6771f7]
:0(__GI_abort)[0x7f58ea6788e8]
addr2line: 'mysqld': No such file
mysqld(+0x424455)[0x557a889b0455]
mysqld(+0xa5c6af)[0x557a88fe86af]
mysqld(+0xa69f8e)[0x557a88ff5f8e]
mysqld(+0x8a6a88)[0x557a88e32a88]
mysqld(+0x964a35)[0x557a88ef0a35]
mysqld(+0x84c86c)[0x557a88dd886c]
mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x64)[0x557a88bfebf4]
mysqld(+0x4edef0)[0x557a88a79ef0]
mysqld(_Z11plugin_initPiPPci+0x9a2)[0x557a88a7b7b2]
mysqld(+0x447991)[0x557a889d3991]
mysqld(_Z11mysqld_mainiPPc+0x1e19)[0x557a889d8d69]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f58ea663c05]
addr2line: 'mysqld': No such file
mysqld(+0x440ded)[0x557a889ccded]
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.
2019-02-15 11:48:56 140238374807680 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:48:56 140238374807680 [Warning] InnoDB: Using innodb_file_format_max is deprecated and the parameter may be removed in future releases. See https://mariadb.com/kb/en/library/xtradbinnodb-file-format/
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Uses event mutexes
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Compressed tables use zlib 1.2.7
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Using Linux native AIO
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Number of pools: 1
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Using SSE2 crc32 instructions
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Initializing buffer pool, total size = 512M, instances = 1, chunk size = 128M
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Completed initialization of buffer pool
2019-02-15 11:48:56 140235987388160 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Opened 8 undo tablespaces
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Highest supported file format is Barracuda.
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Starting crash recovery from checkpoint LSN=56530
2019-02-15 11:48:56 140238374807680 [ERROR] InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE for redo log record 1 (page 1:0) at 56539.
2019-02-15 11:48:56 140238374807680 [ERROR] InnoDB: ############### CORRUPT LOG RECORD FOUND ##################
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Log record type 1, page 1:0. Log parsing proceeded successfully up to 56539. Previous log record type 31, is multi 1 Recv offset 9, prev 11764
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Hex dump starting 9 bytes before and ending 100 bytes after the corrupted record:
len 109; hex 38000000000000dcd201010000ae80ea040100003a033b01020201020018030801020032000000000008010200f2000000000008010201b20000000000080102027200000000000801020332000000000008010203f2000000000008010204b200000000000801020572000000; asc 8 : ; 2 r 2 r ;
2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Set innodb_force_recovery to ignore this error.
2019-02-15 11:48:56 140238374807680 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2019-02-15 11:48:57 140238374807680 [Note] InnoDB: Starting shutdown...
2019-02-15 11:48:57 0x7f8bca83a880 InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.22/storage/innobase/fil/fil0fil.cc line 746
InnoDB: Failing assertion: UT_LIST_GET_LEN(fil_system->LRU) > 0
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 mysqld 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.
190215 11:48:57 [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.2.22-MariaDB-log
key_buffer_size=8388608
read_buffer_size=2097152
max_used_connections=0
max_threads=3002
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 12368366 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...
stack_bottom = 0x0 thread_stack 0x49000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x559f483afd6e]
mysys/stacktrace.c:268(my_print_stacktrace)[0x559f47e31665]
sigaction.c:0(__restore_rt)[0x7f8bca4495e0]
:0(__GI_raise)[0x7f8bc89561f7]
:0(__GI_abort)[0x7f8bc89578e8]
ut/ut0rbt.cc:218(rbt_tree_add_child(ib_rbt_t const*, ib_rbt_bound_t*, ib_rbt_node_t*) [clone .isra.4] [clone .part.5])[0x559f47be5455]
fil/fil0fil.cc:746(fil_node_close_file(fil_node_t*))[0x559f4821d6af]
:0(fil_close_all_files())[0x559f4822af8e]
log/log0log.cc:2148(logs_empty_and_mark_files_at_shutdown())[0x559f48067a88]
srv/srv0start.cc:2818(innodb_shutdown())[0x559f48125a35]
handler/ha_innodb.cc:3613(innobase_init(void*))[0x559f4800d86c]
sql/handler.cc:521(ha_initialize_handlerton(st_plugin_int*))[0x559f47e33bf4]
sql/sql_plugin.cc:1416(plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool))[0x559f47caeef0]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0x9a2)[0x559f47cb07b2]
sql/mysqld.cc:5295(init_server_components())[0x559f47c08991]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x1e19)[0x559f47c0dd69]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x7f8bc8942c05]
/usr/sbin/mysqld(+0x440ded)[0x559f47c01ded]
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.

 Comments   
Comment by Elena Stepanova [ 2019-02-19 ]

marko, thiru, does it look any familiar to you?

Comment by Marko Mäkelä [ 2019-02-19 ]

yue, would it be possible for you to upload an archive of the data directory (or at least the ib_logfile* files), so that we can analyze it? It looks like it is small and there cannot be much data in it. If you think that there could be anything confidential in the files, you can use ftp://ftp.mariadb.com and let us know the file name. Else, please just attach the file to this ticket.

The actual error is this one, which suggests that the redo log was not written correctly before the restart:

2019-02-15 11:48:56 140238374807680 [ERROR] InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE for redo log record 1 (page 1:0) at 56539.

There is also this follow-up error:

InnoDB: Failing assertion: UT_LIST_GET_LEN(fil_system->LRU) > 0

And there is the third error that no crash recovery should be needed after mysql_install_db. Did the server crash during that? If so, why and how?

Could you find and attach the MariaDB server logs from the database initialization? Or could you show the exact steps to reproduce the problem, starting from installing MariaDB?

thiru noticed this message:

2019-02-15 11:48:56 140238374807680 [Note] InnoDB: Opened 8 undo tablespaces

At database initialization, undo tablespaces should be created from tablespace ID 1 onwards. That is, the undo tablespaces should have IDs 1 to 8. The MLOG_FILE_NAME records are written for .ibd files only, not for undo tablespaces. A copy of the datadir and the configuration would help us understand why InnoDB might not identify tablespace 1 as an undo tablespace. MDEV-18639 is possibly related to this.

Generated at Thu Feb 08 08:45:25 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.