線上Redis偶發性連接失敗排查記

問題過程

輸入法業務於12月12日上線了詞庫接受業務，對部分用戶根據用戶uuid判斷進行回傳，在12月17日早上8點多開始出現大量的php報錯（Redis went away），報錯致使了大量的連接積累，瞬間服務器的80端口堆積到了2w多致使了接受計費日誌的接口所有返回超時，丟失了1小時的結費數據。

報錯內容以下：

[17-Dec-2018 01:32:51 UTC] PHP Fatal error:  Uncaught exception 'RedisException' with message 'Redis server went away' in /opt/case/xxx/UuidForRedis.php:75
Stack trace:
#0 /opt/case/xxx/UuidForRedis.php(75): Redis->auth('KangDuiShiWei')
#1 /opt/case/xxx/UuidForRedis.php(59): UuidForRedis->connectRedis()
#2 /opt/case/xxx/pinyin/cloud_switch.php(160): UuidForRedis->__construct()
#3 /opt/case/xxx/cloud_config_new.php(187): include('/opt/case/updat...')
#4 {main}
  thrown in /opt/case/xxx/UuidForRedis.php on line 75

排查過程：

收到服務器的80端口報警後，查看php錯誤是Redis連接超時，因Redis連接的時候設置的超時是10s，因此致使了大量的80端口堆積，形成了該機組的全部業務都其餘接口所有都出現了5xx的超時錯誤。

線上解決：

連接Redis的時候增長超時設置，並設置爲1秒，當Redis有連接問題的時候不會操做請求接口等待超時，上線後解決。

疑問：

那麼如今你可能就有疑問了，redis爲何會時不時的就出現了Redis went away的錯誤呢？而且在併發高的時候愈加明顯，是否是redis併發扛不住了？

Redis排查過程

日誌收集

一、 該Redis是一個公共uuid平臺，確認線上全部連接是否都加了超時，沒有所有加上並設置爲1秒，並上線

二、挑選3個業務對Redis連接增長try catch捕獲並將異常日誌記錄到文本再等待分析

錯誤部分摘要：

2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:00:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:05:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:10:06 Redis server went away
2018-12-20 08:15:06 Redis server went away

排查過程

聯繫運維，先考慮從如下步驟依次排查問題的緣由：

• 內網網絡問題

• redis錯誤日誌
• redis的慢日誌
• 防火牆的配置
• 系統錯誤日誌

• 持久化配置

第一步：內網網絡問題猜想

該問題實際很差測試重現，經過實際測試代碼測試和業務日誌狀況分析，排查該問題

第二步：查看Redis錯誤日誌

Redis錯誤日誌在redis.conf中的logfile配置中，查看確認後無異常

第三步：查看redis的慢日誌

經過連接redis-cli 輸入slowlog get查看最近128條的慢日誌信息，從慢日誌上分析除了有keys的異常命令外其餘都表現正常，能夠再排除，繼續往下排查

部分信息以下：
27.0.0.1:6379> SLOWLOG get
 1) 1) (integer) 52
    2) (integer) 1545183329
    3) (integer) 58086
    4) 1) "KEYS"
       2) ""
    5) "172.16.30.154:40135"
    6) ""
 2) 1) (integer) 51
    2) (integer) 1545182639
    3) (integer) 68437
    4) 1) "KEYS"
       2) ""
    5) "172.16.30.154:28131"
    6) ""

Redis的慢日誌爲啥會有keys命令，經過咱們排查發現全部的請求是經過在線Redis平臺過去的，由於Redis是單進程單線程的，通過評估以爲該操做仍是有必定風險，因此咱們就暫時關閉了全部在線redis平臺的查看權限

第四步：查看防火牆的配置

當前這裏所說的防火牆不是防火牆配置錯了，那種錯誤是全部的連接都會被拒絕，如今的問題是時不時的會出現Redis went away錯誤，據某業務數據統計，1小時55萬請求里約有300多請求出現了該問題。

檢查iptables是否打開了nat轉發模塊，iptables在高併發鏈接時丟包，可能致使鏈接超時ip_conntrack: table full, dropping packet，與運維確認後未開啓該模塊，排查了改點。

具體參考該網頁關於iptables的說明：https://zhangxugg-163-com.iteye.com/blog/2404170

第五步：查看系統錯誤日誌

運維登陸該Redis機器，查看系統message裏var/log/message是否有相關的錯誤信息，排查後錯誤信息正常。

第六步：redis的持久化配置

排查到這裏還有一個重要的配置不能錯過，redis的持久化配置rdb和aof都有可能致使阻塞給客戶端連接操做了連接超時的狀況。

先排查默認的持久化配置，經過命令和配置文件查看redis的rdb配置以下，aof未開啓可忽略

save 900 1 // 900內,有1條寫入,則產生快照
save 300 1000 // 若是300秒內有1000次寫入,則產生快照
save 60 10000 // 若是60秒內有10000次寫入,則產生快照

先關閉持久化配置，並觀察線上的錯誤信息是否有變化

config set save ""

關閉後觀察了1小時未有特別明顯的變化，繼續排查

第七步：排查是否phpredis擴展的版本

備註：php機器的版本是5.3，redis擴展的版本爲xxx，線上Redis的版本是4.0

這個其實很差下定論，可是湊巧該業務還鏈接了另外一臺Redis機器，該Redis的版本也是4.0版本，但從收集的錯誤日誌來看未出現任何錯誤信息，因此反向推論能夠得出Redis擴展的版本並沒有問題。

繼續思考，排查ing...

但從最近收集到的錯誤日誌來看，有一個有規律的特徵，每隔5分鐘的05秒左右就會規律性的出現錯誤，這個點的數據應該引發警覺，有規律每隔5分鐘出現一次，是否是有crontab再定時作持久化rdb呢？

聯繫運維再驗證一下：

經過redis-cli monitor將最近5分鐘的監控日誌所有dump到文本文件中，而後對文本文件的命令進行分析，未發現異常的命令狀況。

後續補充：redis的save和bgsave並不會在monitor監控列表裏出現，但從其餘方面驗證了沒有業務使用命令行進行了定時的save或bgsave操做

第八步：查看crontab配置

是否是crontab有5分鐘一次的相關配置，的確找到了一條，這個你們一下就會比較熟悉，公司全部機器都會有定時同步時間的：

*/5 * * * *  /usr/sbin/ntpdate -s xxx || /usr/bin/rdate -s xxx; /sbin/hwclock -w

這個應該不會有問題了，可是該排查的都排查了，先去掉再看看狀況：

5min

5min

5min

...

再查看3個業務線上的錯誤日誌，日誌所有變少了，從有規律的5分鐘出錯10來條，變成了1小時只有幾條錯誤，另兩個業務無錯誤了。

你可能也會一下就會聯想就是這個問題了，可是爲何更新時間會影響redis操做呢，這個理論上都關聯不上了，咱們在反向驗證一下，把crontab再打開再觀察錯誤狀況，若是錯誤又回來了那確定就是這玩意致使的了。

繼續分析crontab的命令，把定時關掉，手動執行命令再觀察業務機器是否有報錯信息：

① 執行ntpdate命令，走的是udp協議，機房封了該協議，該命令返回是失敗的，執行並沒有影響排除

② 執行rdate命令，業務機器未發現錯誤，排除

③執行/sbin/hwclock -w命令，業務機器發現錯誤！！！發現錯誤！！！穩定重現！！！

看到這裏，那麼你關心的結果來了：

/sbin/hwclock -w在執行的過程當中會致使Redis的客戶端連接出現Redis Went away現象。

但使用相同方法在測試環境未能重現現象

結論

/sbin/hwclock -w命令在執行的過程當中會致使php客戶端鏈接Redis服務器出現必定概率的Redid Went away錯誤，該命令通常執行時間約1-2秒，因此就出現了以前每隔5分鐘就定時出現一個錯誤信息。

後續爲何該命令會影響Redis的服務呢，據與其餘業務瞭解不少軟件都依賴於時間服務，時間服務的變更都會影響到相關業務的服務提供。

後續優化

一、 全部業務連接第三方的api或服務，好比curl、redis、mysql等都須要設置超時

二、Redis設置超時時間建議最大爲1秒，根據業務能夠減小到毫秒，超時後須要有異常捕獲