问题描述
在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
AI 代码解读
以下日志是 RDS 实例特有的日志，RDS实例会将用户的重要操作记录在错误日志中。
150525 15:30:52 [Note] User 'userxx' issued shutdown command
AI 代码解读
从日志可以看出：
- 实例是正常关闭的
- 用户在极短的时间内执行了多次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;
}
AI 代码解读
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
AI 代码解读
差不多在同一时刻系统出现较多的软中断，导致获取系统时间出现错误，即超过2038年或小于0。
改进
从错误日志中我们表面上看到普通用户执行了shutdown命令，这个带来了疑惑和误导。因此我们做了如下改进：
- 此种情况下，在错误日志中打印详细的日志信息，说明shutdown是由于时间获取错误导致；
- 增加重试机制，在第一次获取时间不合法情况下，不直接执行shutdown，而是增加重试重新获取时间，如果还是不合法，再执行shutdown。
