MySQL · 捉虫动态 · 任性的 normal shutdown

最后更新于:2022-04-01 10:39:54

## 问题描述 在RDS生产环境中,一个MySQL实例莫名地被shutdown了, 日志中有如下信息: ~~~ 150525 15:30:52 [Note] User 'userxx' issued shutdown command 150525 15:30:52 [Note] /path/to/mysqld: Normal shutdown 150525 15:30:52 [Note] Stop asynchronous binlog_dump to slave (server_id: xxxxx) 150525 15:30:52 [Note] Event Scheduler: Killing the scheduler thread, thread id xxx 150525 15:30:52 [Note] Event Scheduler: Waiting for the scheduler thread to reply 150525 15:30:52 [Note] Event Scheduler: Stopped 150525 15:30:52 [Note] Event Scheduler: Purging the queue. 0 events 150525 15:30:53 [Note] User 'userxx' issued shutdown command 150525 15:31:07 [Note] Slave I/O thread exiting, read up to log 'log.xxxxx', position xxxxxx 150525 15:31:07 [Note] Error reading relay log event: slave SQL thread was killed 150525 15:31:09 [Note] User 'userxx' issued shutdown command ~~~ 以下日志是 RDS 实例特有的日志,RDS实例会将用户的重要操作记录在错误日志中。 ~~~ 150525 15:30:52 [Note] User 'userxx' issued shutdown command ~~~ 从日志可以看出: 1. 实例是正常关闭的 2. 用户在极短的时间内执行了多次shutdown命令 ## 问题分析 首先我们来查看用户userxx信息,比较奇怪的是,用户userxx为普通用户,并没有执行shutdown的权限。 第一感觉很可能是MySQL权限模块出现了bug, 导致普通用户也可以执行shutdown命令。于是在一个测试实例上,建立相同权限的同名用户,验证发现userxx确实没有权限执行shutdown命令。 进一步从源码中来分析,查找源码中所有可能执行shutdown的路径。从源码中扫描COM_SHUTDOWN 出现的地方,于是在`dispatch_command`函数中发现一处比较可疑的地方,代码如下: ~~~ thd->set_time(); if (!thd->is_valid_time()) { /* If the time has got past 2038 we need to shut this server down We do this by making sure every command is a shutdown and we have enough privileges to shut the server down TODO: remove this when we have full 64 bit my_time_t support */ thd->security_ctx->master_access|= SHUTDOWN_ACL; command= COM_SHUTDOWN; } ~~~ MySQL 每次执行一条命令前,会获取一个系统当前时间(`thd->set_time()`),如果获取的时间不合法(超过2038年或小于0),那么此条命令会自动转为shutdown命令。 如果用户多个连接并发执行命令,并且获取的时间不合法,那么每个连接都会执行shutdown命令,这和我们前面看到的日志中的现象很吻合。 看来问题集中在为什么获取时间会不合法? 最可能的原因是当前主机系统时间设置超过了2038, 于是查看系统时间,然而并没有如我们所愿,系统时间是正常的。 最后我们从系统日志中发现了端倪, ~~~ May 25 15:29:49 xxx kernel: : [4768743.131263] [<ffffffff8109bff3>] ? ktime_get+0x63/0xe0 May 25 15:29:49 xxx kernel: : [4768743.131267] [<ffffffff810726f7>] ? __do_softirq+0xb7/0x1e0 May 25 15:29:49 xxx kernel: : [4768743.131271] [<ffffffff8100c24c>] ? call_softirq+0x1c/0x30 May 25 15:29:49 xxx kernel: : [4768743.131274] [<ffffffff8100de85>] ? do_softirq+0x65/0xa0 May 25 15:29:49 xxx kernel: : [4768743.131276] [<ffffffff810724e5>] ? irq_exit+0x85/0x90 ~~~ 差不多在同一时刻系统出现较多的软中断,导致获取系统时间出现错误,即超过2038年或小于0。 ## 改进 从错误日志中我们表面上看到普通用户执行了shutdown命令,这个带来了疑惑和误导。因此我们做了如下改进: 1. 此种情况下,在错误日志中打印详细的日志信息,说明shutdown是由于时间获取错误导致; 2. 增加重试机制,在第一次获取时间不合法情况下,不直接执行shutdown,而是增加重试重新获取时间,如果还是不合法,再执行shutdown。
';