MySQL 实例无法启动的问题分析及解决-巨人网络通讯

MySQL 实例无法启动的问题分析及解决

前言

前几天，有位朋友微信联系我，告知一个生产数据库，在机器宕机恢复后，实例启动失败，而且该实例没有做任何的高可用、容灾、备份等，对业务影响非常大，希望能够协助排查一下，我也在第一时间就加入到排查中。

场景分析

（1）首先查看错误日志，报错很清晰"Could not open log file"，无法打开日志文件

2021-01-06 13:23:51 20464 [ERROR] Failed to open log (file 'something is definitely wrong and this may fail.', errno 2)
2021-01-06 13:23:51 20464 [ERROR] Could not open log file
2021-01-06 13:23:51 20464 [ERROR] Can't init tc log
2021-01-06 13:23:51 20464 [ERROR] Aborting

（2）看到上述报错后，当然就应该想到，检查下my.cnf配置是否正确、日志目录和权限是否正确，但排查并未发现问题

# less my.cnf
datadir=/var/lib/mysql
log-bin=mysql-bin
relay-log=relay-bin

# ls -lrt
-rw-rw---- 1 mysql mysql 1073761373 Jan 4 06:18 mysql-bin.007351
-rw-rw---- 1 mysql mysql 1073755587 Jan 4 09:26 mysql-bin.007352
-rw-rw---- 1 mysql mysql 1073777045 Jan 4 12:07 mysql-bin.007353
-rw-rw---- 1 mysql mysql 1073742801 Jan 4 15:12 mysql-bin.007354
-rw-rw---- 1 mysql mysql 1074087344 Jan 4 18:13 mysql-bin.007355
-rw-rw---- 1 mysql mysql 1073869414 Jan 4 21:32 mysql-bin.007356
-rw-rw---- 1 mysql mysql 1073771900 Jan 5 00:16 mysql-bin.007357
-rw-rw---- 1 mysql mysql 213063247 Jan 5 01:00 mysql-bin.007358
-rw-rw---- 1 mysql mysql 1073753668 Jan 5 02:11 mysql-bin.007359
-rw-rw---- 1 mysql mysql 671219722 Jan 5 03:31 mysql-bin.007360
-rw-rw---- 1 mysql mysql 1073774928 Jan 5 07:34 mysql-bin.007361
-rw-rw---- 1 mysql mysql 1073845285 Jan 5 11:33 mysql-bin.007362
-rw-rw---- 1 mysql mysql 1073756444 Jan 5 15:37 mysql-bin.007363
-rw-rw---- 1 mysql mysql 1073790555 Jan 5 19:37 mysql-bin.007364
-rw-rw---- 1 mysql mysql 1073768027 Jan 5 23:59 mysql-bin.007365
-rw-rw---- 1 mysql mysql 311398643 Jan 6 01:00 mysql-bin.007366
-rw-rw---- 1 mysql mysql 1071242043 Jan 6 03:31 mysql-bin.007367
-rw-rw---- 1 mysql mysql 1010516229 Jan 6 07:27 mysql-bin.007368
-rw-rw---- 1 mysql mysql 1651 Jan 6 07:27 mysql-bin.index
-rw-rw---- 1 mysql mysql 1073741824 Jan 6 12:08 ib_logfile1
-rw-r--r-- 1 mysql mysql 183 Jan 6 13:23 VM_58_10_centos-slow.log
-rw-rw---- 1 mysql mysql 1073741824 Jan 6 13:23 ib_logfile0
-rw-rw---- 1 mysql mysql 7492941 Jan 6 13:23 VM_58_10_centos.err

（3）报错有一个非常奇怪的点，file 'something is definitely wrong and this may fail.' ，为什么日志文件名会那么奇怪呢？这里需要知道的是，mysql-bin.index记录了binlog相关信息，MySQL实例启动时需要读取该文件获取信息；那接下来就检查一下该文件，发现果然有问题，mysql-bin.index后半部分错误写入了错误日志的内容，从而导致实例启动时读取到错误内容(当作binlog日志文件进行处理)报错失败

# cat mysql-bin.index
./mysql-bin.007351
./mysql-bin.007352
./mysql-bin.007353
./mysql-bin.007354
./mysql-bin.007355
./mysql-bin.007356
./mysql-bin.007357
./mysql-bin.007358
./mysql-bin.007359
./mysql-bin.007360
./mysql-bin.007361
./mysql-bin.007362
./mysql-bin.007363
./mysql-bin.007364
./mysql-bin.007365
./mysql-bin.007366
./mysql-bin.007367
./mysql-bin.007368
23:27:31 UTC - 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.
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.

key_buffer_size=16777216
read_buffer_size=3145728
max_used_connections=523
max_threads=800
thread_count=522
connection_count=522
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9037821 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 = 0 thread_stack 0x40000
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.

（4）原因定位后，解决办法就是将mysql-bin.index文件备份后，手动进行修复，随后启动实例成功

# ./mysql start
Starting MySQL.... SUCCESS! 
Checking mysql connection: connection ok!

# ps -ef | grep mysqld
root 22955 1 0 13:30 pts/5 00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/var/lib/mysql --pid-file=/var/lib/mysql/VM_58_10_centos.pid
mysql 23733 22955 24 13:30 pts/5 00:00:05 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/lib/mysql/VM_58_10_centos.err --open-files-limit=20000 --pid-file=/var/lib/mysql/VM_58_10_centos.pid --socket=/var/lib/mysql/mysql.sock --port=3306
root 32075 14929 0 13:30 pts/5 00:00:00 grep mysqld