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

## 问题描述 在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。