MySQL 无报错日志启动不成功案例分析

本文首发：https://www.modb.pro/db/1763756312957128704

案例概述

最近遇到一个案例，MySQL 启动不成功，无报错日志，需要分析解决，然后附了一张截图（已脱敏处理）如下：

其中 MySQL 数据库的版本为： MySQL 5.7.44

其中./startcm3307.sh 的内容如下：

/data/cm3307/mysql/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql &

屏幕有输出： mysqld_safe Logging to '/data/cm3307/mysqllog/cm3307_error.log'. mysqld_safe日志记录到 /data/cm3307/mysqllog/cm3307_error.log

案例处理

那就先检查下日志文件，发现文件是空的，权限也正确都是mysql

[root@liups data]# cat /data/cm3307/mysqllog/cm3307_error.log
[root@liups data]# ls -l  /data/cm3307/mysqllog/cm3307_error.log
-rw-r--r-- 1 mysql mysql 0 Mar  2 09:22 /data/cm3307/mysqllog/cm3307_error.log
[root@liups data]# ls -al ./cm3307
total 16
drwxr-xr-x 4 mysql mysql 4096 Mar  2 09:23 .
drwxr-xr-x 5 root  root  4096 Mar  2 09:22 ..
drwxr-xr-x 2 mysql mysql 4096 Mar  2 09:23 mysqldata
drwxr-xr-x 2 mysql mysql 4096 Mar  2 09:22 mysqllog

在这里我又特意启动的时候指定了日志文件的位置进行启动，去掉后台启动，这样启动日志文件仍然为空。

[root@liups cm3307]# /usr/local/cm3307/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql --log-error=/tmp/cnwww.err
Logging to '/tmp/cnwww.err'.
2024-02-29T07:37:21.201831Z mysqld_safe Starting mysqld daemon with databases from /data/cm3307/mysqldata
2024-02-29T07:37:21.401062Z mysqld_safe mysqld from pid file /data/cm3307/mysqldata/cm3307.pid ended
[root@liups cm3307]# touch /tmp/cnwww.err
[root@liups cm3307]# chown mysql:mysql /tmp/cnwww.err 
[root@liups cm3307]# chmod 777 /tmp/cnwww.err 
[root@liups cm3307]# /usr/local/cm3307/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql --log-error=/tmp/cnwww.err
2024-02-29T07:38:07.319574Z mysqld_safe Logging to '/tmp/cnwww.err'.
2024-02-29T07:38:07.342685Z mysqld_safe Starting mysqld daemon with databases from /data/cm3307/mysqldata
2024-02-29T07:38:07.539972Z mysqld_safe mysqld from pid file /data/cm3307/mysqldata/cm3307.pid ended
[root@liups cm3307]# cat /tmp/cnwww.err 
[root@liups cm3307]# ll /tmp/cnwww.err 
-rwxrwxrwx 1 mysql mysql 0 Feb 29 15:37 /tmp/cnwww.err

也就是问题不在日志文件配置以及权限了，继续排查，在这期间我也使用 strace 来跟踪，去查找 close、exit等信息也是一堆杂七杂八的信息，看着眼晕,遂放弃。

由于这个库是通过xtrabakcup 恢复过来的，检查了 xtrabakcup的日志，也都正常，全部都是 completed OK!。

后来确认xtrabackup 的目标库和源库的版本不一致，怀疑是这个问题，然后调整目标库的版本跟源库版本相同，现象依旧。那这显然是问题排查进入了歧路。

互联网是个好东西，搜索发现 mysqld_safe无法启动没有日志 这个文章，竟然是一样的现象，也是mysqld_safre 无日志，实际上我在之前搜索的时候都是在搜索关键字mysql 无法启动没有日志，后来发现了问题发现是 mysqld_safe 引起的。如果通过搜索 mysqld_sql 无日志就可以搜索到了。我这里通过 mysqld来启动

[root@liups:/root]# /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --user=mysql
2024-03-01T10:10:26.689364+08:00 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2024-03-01T10:10:26.689450+08:00 0 [Note] /data/cm3307/mysql/bin/mysqld (mysqld 5.7.36-log) starting as process 12867 ...
2024-03-01T10:10:26.691139+08:00 0 [ERROR] COLLATION 'utf8mb4_general_ci' is not valid for CHARACTER SET 'latin1'
2024-03-01T10:10:26.691161+08:00 0 [ERROR] Aborting

2024-03-01T10:10:26.691174+08:00 0 [Note] Binlog end
2024-03-01T10:10:26.691322+08:00 0 [Note] /data/cm3307/mysql/bin/mysqld: Shutdown complete

这错误就很明显了：[ERROR] COLLATION 'utf8mb4_general_ci' is not valid for CHARACTER SET 'latin1'

检查了参数文件，发现 COLLATION 确实设置的 utf8mb4_general_ci，但是没找到设置数据库字符集的配置，也就是参数文件中没有设置数据库的字符集，那咱们知道在 MySQL 5.7 默认的数据库字符集是 latin1，然后排序字符集设置的 utf8mb4_general_ci ，从报错来看，也就是对于排序规则utf8mb4_general_ci对字符集latin1无效的。进一步确认发现数据库源库的字符集是设置为utf8mb4，虽然参数文件里没有设置数据库的字符集的参数，但是经过查看发现有 init_connect='SET NAMES utf8mb4' 这样一个配置，也就是数据库在进行连接的时候设置当前字符集是 utf8mb4，这个很显然是库能启动的情况下，普通用户可以连接的时候可以自动设置SET NAMES utf8mb4 ，但是现在库都没启动，库的字符集就是 latin1，那很显然排序规则 utf8mb4_general_ci 与 latin1 是有冲突的，这就导致无法启动。

知道了原因，就在参数中新增了设置数据库字符集为utf8mb4 的参数：

character-set-server= utf8mb4

之后再次启动发现日志再次报： [ERROR] unknown variable 'sam_repair_threadscharacter-set-server=utf8mb4'

也就是无效的参数 sam_repair_threadscharacter-set-server，删除了此参数，启动数据库正常。

问题解决。

案例复盘

我查了下 sam_repair_threadscharacter-set-server 这个参数，实际上MySQL 中是没有这个参数的，那这个参数配置是如何产生的？
越看越觉得怎么这么眼熟呢，sam_repair_threadscharacter-set-server=utf8mb4 可以看到这个配置的后半部分不就是设置数据库字符集的配置嘛 character-set-server=utf8mb4

那sam_repair_threads 是个什么参数呢。查询了官方手册也是不存在的，但是，官方手册是有myisam_repair_threads 这个参数的，我找了个 MySQL 5.7 的库，查询了下确实有这个参数，看看 sam_repair_threads 是不是跟 myisam_repair_threads很像，也就是把前面的myi给删掉了，那sam_repair_threadscharacter-set-server=utf8mb4 的来源就很好解释了，也就是在修改数据库参数的时候，经过删删减减，不小心把设置数据库字符集的参数character-set-server=utf8mb4跟上一行的 myisam_repair_threads的参数删到一行了，然后又不知道怎么操作把 myisam_repair_threads 参数的myi给删除了。当然啦，这只是猜测。。

mysql> show variables like 'myisam_repair_threads';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| myisam_repair_threads | 1     |
+-----------------------+-------+
1 row in set (0.01 sec)

咱们再来复盘下为什么mysqld_safe不产生日志呢。
我们知道mysqld_safe 是一个shell 脚本封装了 mysqld来进行安全启动，既然是shell 那通过sh -x来跟踪下，其实我看了下mysqld_safe的具体脚本，一堆判断，看着有点懵，脚本有 985 行，就直接 sh -x 来跟踪看看吧。具体如下：

sh -x  /data/cm3307/mysql/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql

sh -x 的结果有很多（2533 行），重定向到 log.txt

sh -x  /data/cm3307/mysql/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql 2>&1|tee -a log.txt

[root@liups:/root]# cat /data/cm3307/mysql/bin/mysqld_safe |wc -l
985
[root@liups:/root]# sh -x  /data/cm3307/mysql/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql 2>&1|tee -a log.txt
[root@liups:/root]# cat log.txt|wc -l
2533

初步看了下，mysqld的启动信息被重定向到了 /dev/null

cat log.txt |grep mysqld|grep '/dev/null'
+ cmd='nohup /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --basedir=/data/cm3307/mysql --datadir=/data/cm3307/mysqldata --plugin-dir=/usr/local/cm3307/lib/plugin --user=mysql  --log-error=/data/cm3307/mysqllog/cm3307_error.log --open-files-limit=65535 --pid-file=cm3307.pid --socket=/tmp/cm3307.sock --port=3307 < /dev/null'
+ eval_log_error 'nohup /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --basedir=/data/cm3307/mysql --datadir=/data/cm3307/mysqldata --plugin-dir=/usr/local/cm3307/lib/plugin --user=mysql  --log-error=/data/cm3307/mysqllog/cm3307_error.log --open-files-limit=65535 --pid-file=cm3307.pid --socket=/tmp/cm3307.sock --port=3307 < /dev/null'
+ cmd='nohup /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --basedir=/data/cm3307/mysql --datadir=/data/cm3307/mysqldata --plugin-dir=/usr/local/cm3307/lib/plugin --user=mysql  --log-error=/data/cm3307/mysqllog/cm3307_error.log --open-files-limit=65535 --pid-file=cm3307.pid --socket=/tmp/cm3307.sock --port=3307 < /dev/null'
+ cmd='nohup /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --basedir=/data/cm3307/mysql --datadir=/data/cm3307/mysqldata --plugin-dir=/usr/local/cm3307/lib/plugin --user=mysql  --log-error=/data/cm3307/mysqllog/cm3307_error.log --open-files-limit=65535 --pid-file=cm3307.pid --socket=/tmp/cm3307.sock --port=3307 < /dev/null > /dev/null 2>&1'
+ eval 'nohup /data/cm3307/mysql/bin/mysqld --defaults-file=/etc/cm3307.cnf --basedir=/data/cm3307/mysql --datadir=/data/cm3307/mysqldata --plugin-dir=/usr/local/cm3307/lib/plugin --user=mysql  --log-error=/data/cm3307/mysqllog/cm3307_error.log --open-files-limit=65535 --pid-file=cm3307.pid --socket=/tmp/cm3307.sock --port=3307 < /dev/null > /dev/null 2>&1'

这就解释了为什么 mysqld_safe 没有输出日志信息了，因为他封装的mysqld 将日志都重定向了 /dev/null。

所以，虽然mysqld_safe 虽然安全，但是在排查错误的时候稍微不太方便。

我顺手修改了下 mysqld_safe 的代码，将几个日志重定向到空的代码 > /dev/null 去掉之后，重新通过 mysqld_safe 来启动数据库，具体信息如下：

[root@liups:/root]# vi  /data/cm3307/mysql/bin/mysqld_safe
[root@liups:/root]# /data/cm3307/mysql/bin/mysqld_safe --defaults-file=/etc/cm3307.cnf --user=mysql
57
2024-03-02T13:10:59.571550Z mysqld_safe Logging to '/data/cm3307/mysqllog/cm3307_error.log'.
nohup: ignoring input and appending output to ‘nohup.out’
2024-03-02T13:10:59.591554Z mysqld_safe Starting mysqld daemon with databases from /data/cm3307/mysqldata
nohup: appending output to ‘nohup.out’
2024-03-02T13:10:59.774138Z mysqld_safe mysqld from pid file /data/cm3307/mysqldata/cm3307.pid ended

很明显多了 nohup: ignoring input and appending output to ‘nohup.out’ 也就是 nohup 启动 mysqld的时候日志默认是写到nohup.out，我检查当前目录下的nohup.out

2024-03-02T21:10:59.759723+08:00 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2024-03-02T21:10:59.759809+08:00 0 [Note] /data1/canarymysql3307/mysql/bin/mysqld (mysqld 5.7.36-log) starting as process 24043 ...
2024-03-02T21:10:59.761453+08:00 0 [ERROR] COLLATION 'utf8mb4_general_ci' is not valid for CHARACTER SET 'latin1'
2024-03-02T21:10:59.761481+08:00 0 [ERROR] Aborting

2024-03-02T21:10:59.761495+08:00 0 [Note] Binlog end
2024-03-02T21:10:59.761611+08:00 0 [Note] /data1/canarymysql3307/mysql/bin/mysqld: Shutdown complete

很明显就是 mysqld 启动的日志信息，这样排查问题就很明显了。

案例解决

综合以上本次的解决方案：
修改参数文件将 sam_repair_threadscharacter-set-server = utf8mb4 参数修改为两部分

myisam_repair_threads=1
character-set-server = utf8mb4

问题完美解决。

原文作者: liups.com

原文链接: http://liups.com/posts/1b0171c4/

许可协议: 知识共享署名-非商业性使用 4.0 国际许可协议