问题描述

在RDS生产环境中，一个MySQL实例莫名地被shutdown了, 日志中有如下信息：

  1. 150525 15:30:52 [Note] User 'userxx' issued shutdown command
  2. 150525 15:30:52 [Note] /path/to/mysqld: Normal shutdown
  3. 150525 15:30:52 [Note] Stop asynchronous binlog_dump to slave (server_id: xxxxx)
  4. 150525 15:30:52 [Note] Event Scheduler: Killing the scheduler thread, thread id xxx
  5. 150525 15:30:52 [Note] Event Scheduler: Waiting for the scheduler thread to reply
  6. 150525 15:30:52 [Note] Event Scheduler: Stopped
  7. 150525 15:30:52 [Note] Event Scheduler: Purging the queue. 0 events
  8. 150525 15:30:53 [Note] User 'userxx' issued shutdown command
  9. 150525 15:31:07 [Note] Slave I/O thread exiting, read up to log 'log.xxxxx', position xxxxxx
  10. 150525 15:31:07 [Note] Error reading relay log event: slave SQL thread was killed
  11. 150525 15:31:09 [Note] User 'userxx' issued shutdown command

以下日志是 RDS 实例特有的日志，RDS实例会将用户的重要操作记录在错误日志中。

  1. 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函数中发现一处比较可疑的地方，代码如下：

  1.     thd->set_time();
  2.     if (!thd->is_valid_time())
  3.     {
  4.       /*
  5.        If the time has got past 2038 we need to shut this server down
  6.        We do this by making sure every command is a shutdown and we
  7.        have enough privileges to shut the server down
  9.        TODO: remove this when we have full 64 bit my_time_t support
  10.       */
  11.       thd->security_ctx->master_access|= SHUTDOWN_ACL;
  12.       command= COM_SHUTDOWN;
  13.     }

MySQL 每次执行一条命令前，会获取一个系统当前时间(thd->set_time())，如果获取的时间不合法(超过2038年或小于0），那么此条命令会自动转为shutdown命令。

如果用户多个连接并发执行命令，并且获取的时间不合法，那么每个连接都会执行shutdown命令，这和我们前面看到的日志中的现象很吻合。

看来问题集中在为什么获取时间会不合法？

最可能的原因是当前主机系统时间设置超过了2038, 于是查看系统时间，然而并没有如我们所愿，系统时间是正常的。

最后我们从系统日志中发现了端倪，

  1. May 25 15:29:49 xxx kernel: : [4768743.131263]  [<ffffffff8109bff3>] ? ktime_get+0x63/0xe0
  2. May 25 15:29:49 xxx kernel: : [4768743.131267]  [<ffffffff810726f7>] ? __do_softirq+0xb7/0x1e0
  3. May 25 15:29:49 xxx kernel: : [4768743.131271]  [<ffffffff8100c24c>] ? call_softirq+0x1c/0x30
  4. May 25 15:29:49 xxx kernel: : [4768743.131274]  [<ffffffff8100de85>] ? do_softirq+0x65/0xa0
  5. May 25 15:29:49 xxx kernel: : [4768743.131276]  [<ffffffff810724e5>] ? irq_exit+0x85/0x90

差不多在同一时刻系统出现较多的软中断，导致获取系统时间出现错误，即超过2038年或小于0。

改进

从错误日志中我们表面上看到普通用户执行了shutdown命令，这个带来了疑惑和误导。因此我们做了如下改进：

  1. 此种情况下，在错误日志中打印详细的日志信息，说明shutdown是由于时间获取错误导致；
  2. 增加重试机制，在第一次获取时间不合法情况下，不直接执行shutdown，而是增加重试重新获取时间，如果还是不合法，再执行shutdown。