某個舊版本業務功能中運行了一個失敗重試的job,因一位離職的同事編碼時未考慮周全出現死循環,導致線上從24日下午2點一直到27日晚9點持續3天一直在刷日志。異常日志內容如下:
2、事故過程分析:
①、根據異常日志內容,初步考慮為redis中緩存的token失效了,后檢查token並與請求方token對比,發現token正確,故排除token過期原因
②、通過grep命令查找更多日志內容后,依然無法顯示更多有用信息(包括調用入口,更多代碼中打印的日志信息等),於是核查所有可能的代碼入口,並依次打印相關日志,結果均未打印有效信息。
③、考慮之前該服務已經接入公司自研的日志鏈調用分析系統,先后根據日志關鍵內容和traceid在系統中查詢,結果發現traceId的調用鏈無法正常顯示,依舊無法找到異常日志准確的入口,后找到故障原因后,架構組同事猜測可能是因為該調用鏈一直未調用結束,導致無法通過traceId來查找調用鏈。
④、由於持續重復調用同一個接口,開始以為是安全問題懷疑被人刷接口(前段時間公司有進行安全驗證),后看到所有日志內容均是由同一個線程所打印的,因此懷疑可能是有死循環存在。后與同事確認,了解到舊版某個業務中有一個失敗訂單重試job,目前已經棄用了,理論上應該不存在問題,然后又找到該job的入口,使用grep命令查看第一行日志,發現仍未打印日志,於是排除了該job的入口。后來發現被迷惑了,因為該job是在7.24下午2點開始的,因為死循環該方法一直沒調用完,所以到27號查找該日志內容時依然未打印。
⑤、后使用jstack命令通過線程名稱最終查找到異常代碼入口,確定事故原因是由於舊版業務的job導致,
該job的部分代碼如下:
可以看到,最外層的for循環的終止條件只能依賴於xxList變量,並且token是在循環外層定義的(這也解釋了為何日志一直顯示token校驗失敗了,因為token是24號的,正常情況token為1小時更新一次),而在job執行過程中,token過期了,因此后面的query方法返 回的code一直不為0,於是進入死循環,導致一直刷日志。
3、事故解決:
找到問題后,重啟了1台服務后觀察一段時間,發現日志恢復正常,於是重啟剩余2台機器,並在es-job中將該job禁用。
4、事故影響分析:
由於只是打印日志,且日志量不大,未對平台核心相關服務產生明顯影響,但由於重復請求服務方,導致對方機器磁盤爆滿后發現了該問題。
5、事故總結:
①、使用for循環時,必須確保循環終止條件能達到,避免產生死循環。
②、良好的日志能有效提升問題定位的效率,有關日志打印規范,請參考阿里巴巴日志規約(http://www.cnblogs.com/dragonsuc/p/6937584.html)
③、對於已經棄用的業務和功能,注意一些舊的job可能產生的影響,如有必要需要停止。
④、盡量通過多角度快速定位問題,比如重復日志就要考慮是否有死循環,熟練使用jstack等命令快來速定位代碼。
如有其他建議和意見,歡迎指出批評。