有了鏈路日誌增強,排查Bug小意思啦!

猿天地發表於2021-01-18

在工作中,相信大家最怕的一件事就是聽到有人在工作群艾特你:某某功能報錯啦。。。

然後你就得屁顛屁顛的去伺服器看日誌,日誌量少還好點,多的話找起來太麻煩了。不太容易直接定位到關鍵地方。

東找找西找找,好不容易找到了報錯的資訊,卻不知道當時的引數資訊是什麼,也不太好復現,太難了。。

改完還得寫故障報告,美好的一天又沒了。

要解決這類的痛點需要做下面幾件事情:

  • 日誌收集
  • 異常告警
  • 日誌增加鏈路
  • API響應增加traceId
  • 異常時列印當前報錯方法的引數
  • 支援除錯模式

日誌收集

要解決的第一個問題就是日誌的集中管理,不然報錯了你得去多臺服務上找錯誤資訊,效率太低了。當然也可以用ansible這種工具來做,最好的還是日誌統計收集起來,通過Web頁面就可以搜尋檢視。

日誌收集的標杆就是ELK啦,不做過多講解。像我們是用的雲服務,收集起來更方便,直接頁面上點點就搞定了。

日誌增加鏈路

日誌增加鏈路跟蹤功能分為兩個步驟,首先系統要有鏈路跟蹤,然後將鏈路資訊整合到日誌中就可以了。

我用的是Spring Cloud Sleuth,主要是Sleuth對很多開源的框架都支援了,也整合了logback這樣的日誌框架,用起來非常方便。

Sleuth預設增強的日誌格式如下:

[${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]

分別是服務名,鏈路ID, 工作單元ID,是否匯入到zipkin中。對於日誌來說最重要的就是traceId了,有了traceId就能將所有系統的日誌串連起來了。

我們也可以自己擴充套件,增加一些其他的資訊放入日誌中。比如:

%X{X-REST-API:-},%X{X-RPC-SERVICE:-},%X{X-ORIGIN-INFO:-},%X{X-USER-ID:-},%X{X-BIZ-NAME:-},%X{X-BIZ-ID:-}
  • X-REST-API:入口API, 全域性透傳
  • X-RPC-SERVICE:入口RPC, 每個服務入口處新增
  • X-ORIGIN-INFO:來源資訊(呼叫方應用名:IP:服務名)
  • X-USER-ID:使用者ID, 全域性透傳
  • X-BIZ-NAME:業務名稱, 全域性透傳, 應用內可替換
  • X-BIZ-ID:業務ID, 全域性透傳, 應用內可替換

有了這些擴充套件的資訊就可以直接從日誌中知道當前請求的入口API是哪個,也知道整個請求經過了哪些服務。

如果我是訂單服務的負責人,當我去排查問題的時候根據日誌就知道當前這個錯誤是上游哪個系統和哪個介面呼叫導致的。

日誌中還帶上了使用者資訊,知道是哪個使用者的請求。

BIZ-ID和BIZ-NAME可以用於業務場景的問題排查,比如下單後就知道訂單ID了,後續就可以將訂單ID追加到日誌中,BIZ-NAME=order, BIZ-ID=20102121212121。

後續有支付,發貨,退款等等訂單相關的操作,日誌中都有訂單ID,需要排查的時候直接根據訂單ID就可以看到整個訂單相關的日誌資訊,前提是打了這些資訊。

異常告警

除了使用者反饋功能異常,開發也應該在第一時間知道出問題了。所以異常告警一定要做。

一般我們的應用分為:服務應用,Job應用,非同步消費應用

服務應用我們可以在統一的異常處理中進行告警,Job應用也可以在統一排程的入口進行告警,非同步消費的也是一樣。

可以通過訊息佇列告警,也可以通過制定日誌的格式,通過記錄日誌的方式,讓日誌收集到日誌平臺,然後配置各種規則進行告警。

異常告警的時候就可以帶上traceId,這樣在發現異常的時候,直接通過traceId去日誌平臺搜尋,就可以看到這個traceId相關的所有日誌,對排錯很有幫助,前提是你列印了關鍵的日誌資訊。

API響應增加traceId

可以通過ResponseBodyAdvice對響應結果進行統一定製,增加traceId響應。這樣在出問題的時候可以通過響應的traceId直接去日誌平臺進行日誌的搜尋。

除了快速排查異常問題之外,對於效能優化的時候,我們也可以直接根據traceId去檢視這個API對應的耗時情況,前提是這個traceId就是跟你們的APM系統一致就行。

異常時列印當前報錯方法的引數

通過前面的操作,我們已經可以在異常的時候獲取一個traceId去排查相關錯誤資訊,也不用去多臺機器隨機找日誌了,極大的提高了問題解決的速度。

只能說這些操作對我們的問題排查起了一半的幫助作用,比如說我現在收到一個告警,然後我去日誌平臺查了相關的日誌,發現某行報錯了。

這個時候也只能是猜測這個地方是有問題的,因為我不知道當時是什麼引數導致這行報錯了。所以如果能在報錯的時候將當前報錯方法的引數列印到日誌中,也就相當於保留了出問題時的現場,解決起問題來就是分分鐘的事。

具體實現方案沒有固定的,最簡單的方式就是寫一個Aspect切到所有業務方法上,當方法丟擲異常的時候記錄引數資訊,切記只在異常的時候做這個記錄的操作,否則對效能影響很大。

效果:

com.xxx.biz.service.impl.GoodsSkuServiceImpl.createSku異常, 引數資訊:{"cspuId":1, stock:10, price:100}
Caused by: java.util.NoSuchElementException: No value present
	at java.util.Optional.get(Optional.java:135)
	at com.xxx.biz.service.impl.GoodsSkuServiceImpl.createSku(GoodsSkuServiceImpl.java:682)

支援除錯模式

支援除錯模式指的是在某些場景下,我們可以復現出錯誤,但是除了當時異常時記錄的引數資訊,還想知道整個請求鏈路的引數和響應。也就是從入口處經過的所有方法都能夠列印出請求和響應資料。

可以定義一個特定的請求頭,在復現問題的時候帶上這個請求頭,由統一的框架去接收這個請求頭,然後在整個鏈路上進行透傳。再結合異常的那個Aspect將引數和結果進行日誌輸出即可。

效果:

xxx.xxxController.makeOrder 引數:xxx
xxx.xxxRpcService.makeOrder 引數:xxx
xxx.xxxStockRpcService.lockStock 引數:xxx
xxx.xxxStockRpcService.lockStock 響應:xxx
xxx.xxxRpcService.makeOrder 響應:xxx
xxx.xxxController.makeOrder 響應:xxx

關於作者:尹吉歡,簡單的技術愛好者,《Spring Cloud微服務-全棧技術與案例解析》, 《Spring Cloud微服務 入門 實戰與進階》作者, 公眾號猿天地發起人。

相關文章