系統上線那點事 - 記一次線上系統故障 - zhukunrong－IT工程師數位筆記本

文章出處

該項目是一個微信轉盤游戲抽獎營銷項目，由于運營營銷時間要求緊迫，開發測試部署上線用了10天不到，有些準備工作并沒有到位，如：

1.由于整體開發在上線前2天才完成，測試了解這個項目需求是在開發的第二周，并沒有充足的時間進行完善的功能，UI機型適配，系統壓力測試。

2.技術上由于合作方的公眾號密鑰并不適合直接給出，所以由對方封裝微信接口獲取所需功能，對方封裝的微信接口給出比較遲,在預定開始時間前三天；

微信的網頁接口授權回調域名只有一個，這個回調域名還有其他應用在使用，不能直接簡單的改為我們部署應用的域名，需要合作方在其內網設置nginx進行http轉發，保證微信的回調能發送到我們的服務器，封裝的API接口測試也要等轉發配置完成才能進行。

此種網絡配置方式也導致了之后遇到的部分用戶頁面無法載入時，排除問題難度加大，不能在自己的機房解決。

3.線上應用機器在最后一天才準備好，tomcat及數據庫部署環境的檢查并沒有完全完成，留下了隱患。如mariadb的binlog功能在設置了my.cnf后仍然沒有生成，部分核心表的索引沒有建完全。

并且活動只有七天，經過估算，認為搖獎壓力大部分應該在應用端，數據庫無壓力，所以配置了10幾臺tomcat及redis緩存，沒有為mariadb配置主從結構做備份，成為了一個單點。

4.機器準備好后由于此時運維也在做監控及log查看基礎設施的整體遷移工作，并且人力緊張，在半天時間內只能做一件事情，所以優先做了服務器監控，這里另一個隱患是告警系統。公司內部的服務器告警系統由支撐部門統一做，認為應該有，所以上線時沒有測試告警功能，埋下了另一顆地雷。

活動前

10：00AM 手機掛代理測試發現由于對方nginx轉發過來的http head頭上的host為對方地址，所以游戲活動的每次請求都會先過對方服務器一遍，再轉發回來。這個轉發在第一次走微信驗證時，這在游戲首頁的延遲影響較大。

10：30AM 還有半小時開始，曾想測試一下將對方代理過來的請求重定向，但由于此前官微推送過消息，在活動開始前,一些零散用戶已經開始訪問活動頁面，但被擋在活動未開始頁面，臨時改程序影響比較大，再加上前一天為了測試接口壓力測試也搞到1點，腦子比較混沌，稍微改了測試下沒有成功，暫時放棄。

活動開始

11：00AM 系統正式開放，用戶已經可以進入轉盤抽獎頁。系統監控正常，系統負載，網絡均沒有異常。

2:00PM 觀察數據庫某表一個常用字段沒有建索引，邏輯上由于只有用戶未登錄時才會查詢一次，考慮到在線上庫做alter index操作可能會對當時時間點的數據庫操作有影響，就沒有補上這個索引。

4：10PM 公司VPN斷開，由于無法連接就沒法工作，幾個開發轉到茶水間去喝水放松。過了一會突然被通知活動頁白屏無法訪問，運維的同事通知說服務器機房的移動入口線路中斷，趕緊通知支撐部門排查原因；同時緊急切換該域名的地址解析到機房電信IP上，等域名生效理論上需要10分鐘。

4：50PM 斷開的機房入口通道恢復，為了保險還是等了一會才將域名解析IP重新切回到移動線路。

5：00PM 又一波官微訂閱號開始推圖文引導用戶進入。

7：00PM 左右程序進行了調整，需要線上程序重新發布，運維同事在高速的回家路上，需要路邊找個地方再將所有war包推送到服務器，等待。同時被告知下一波微信訂閱號開始推送游戲圖文，可能馬上訪問量就會有反應。

7：30PM 幾個人總算有空去找飯吃，悲劇的發現食堂和全家的飯都沒了，只能吃泡面面包了。。。

7：50PM 左右運維反饋將所有war包推送完成。

隨后發現游戲頁面又開始進入緩慢，并且關注公眾號的用戶已經開始不能進入游戲頁面了，返回請關注引導界面。

8：00PM 開始排查錯誤發生原因。查看線上機器tomcat并沒有什么異常，此時登陸數據庫機器發現在命令行下系統響應速度不正常，命令輸入后2，3秒以上才有反應。
再看top負載，cpu負載很不正常，已經超載，系統load也是一樣。

8：30PM 發現數據庫異常后，決定重啟數據庫。

8：45PM systemctl stop db。然后就悲劇了，系統負載下來了，但重新start不起來了， mysql error-log中查啟動問題：

InnoDB: Error: log file ./ib_logfile0 is of different size 0 >5256780 bytes
InnoDB: than specified in the .cnf file 0 1077645824 bytes!
[ERROR] Plugin ‘InnoDB’ init function returned error.
[ERROR] Plugin ‘InnoDB’ registration as a STORAGE ENGINE failed.
[ERROR] Unknown/unsupported storage engine: InnoDB
[ERROR] Aborting

查了下資料，正常shutdown后將logfile0刪除后再啟動能成功，為保險將此文件mv到另外的目錄，再嘗試啟動，仍然起不來，完全暈菜

150703 23:44:27 InnoDB: Could not open or create data files.
150703 23:44:27 InnoDB: If you tried to add new data files, and >it failed here,
150703 23:44:27 InnoDB: you should now edit >innodb_data_file_path in my.cnf back
150703 23:44:27 InnoDB: to what it was, and remove the new >ibdata files InnoDB created
150703 23:44:27 InnoDB: in this failed attempt. InnoDB only >wrote those files full of
150703 23:44:27 InnoDB: zeros, but did not yet use them in any >way. But be careful: do not
150703 23:44:27 InnoDB: remove old data files which contain your >precious data!
150703 23:44:27 [ERROR] Plugin 'InnoDB' init function returned >error.
150703 23:44:27 [ERROR] Plugin 'InnoDB' registration as a >STORAGE ENGINE failed.
150703 23:44:27 [Note] Plugin 'FEEDBACK' is disabled.
150703 23:44:27 [ERROR] Unknown/unsupported storage engine: >innodb
150703 23:44:27 [ERROR] Aborting

此時事情已經開始棘手，這是微信活動第一天上線的周五晚上，從七點多逐漸服務不可用到八點多數據庫shutdown后crash已經過去不短的一段時間了，大量用戶在官微大號消息推送后進入抽獎游戲時被擋在404頁面上不能進入。而且由于之前說的此活動為7天，定義此數據庫為一個臨時庫，沒有掛從庫，也沒有dump備份，現在第一天就居然遇到數據庫崩潰的問題。

部門沒有DBA,處理數據庫不能啟動的問題找不到直接可以咨詢的人，上級給了個其他部門的DBA電話咨詢，遠水解不了近渴，電話里大致聊了下也說不清楚，沒有時間耗在恢復這個數據庫上了。

此時經過商量決定重新初始化一個數據庫虛機，急忙dump了一個原測試線上環境時的老數據庫到新的數據庫上，重新發布應用切換到新數據庫上，讓用戶先能進行游戲再說。

9：55PM 數據庫虛機初始化完成，應用重新上線，幾個開發稍微松了口氣。

10:00PM-1:20AM 此時大腦已經比較遲鈍了，嘗試恢復老數據庫一次失敗后放棄。跟同事reivew這次問題，通過監控數據發現晚7點數據庫突然連接數暴漲，同時CPU負載飆升，但應用服務器并沒有流量暴漲的異常問題，如果應用邏輯沒問題，就暫時只能懷疑是連接池問題（用的是Druid）。當時的負載監控如下圖：