## 問題描述 在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。