Java應用層資料鏈路追蹤（附優雅列印日誌姿勢）

Java3y發表於2022-03-08

我是3y，一年CRUD經驗用十年的markdown程式設計師??‍?常年被譽為優質八股文選手

今天來聊些大家都用得上的東西：資料鏈路追蹤。之前引入了系統的監控來快速定位應用作業系統上的問題，而業務問題呢？在這篇文章中你可以看到用註解的方式列印日誌，也能看到簡易版的全鏈路追蹤是怎麼實現的。

不多BB，開始吧

01、註解日誌列印

日誌的搭建我在austin最開始的前幾篇已經有提及了，之前一直在等我的基友@蠻三刀醬他的日誌元件庫上傳到Maven庫，好讓我使用使用下。在最近，他已經更新了兩個版本，然後傳到了Maven庫了，所以我就來接入了

這個元件庫做的事情就是使用註解的方式來列印日誌資訊，並支援SpEL解析、自定義上下文以及自定義函式。它支援的東西聽起來很牛逼，但說白了就是讓記錄日誌的方式做得更裝逼。我們寫個破程式碼還能裝逼，這誰受得了！這誰頂得住！

現在我已經把註解在方法上定義了，當該方法被呼叫時，它列印了以下的日誌：

看起來很好用，對不對？通過一個註解，我就能把方法的入參資訊列印出來，有bizType和bizId給我們自定義，那就可以很方便地定位出列印日誌的地方了，並且他還貼心把response返回值也輸出到日誌上。

至少在這個介面上，這非常符合我這個場景的需求，我們再通過一張圖稍微重溫下這個send介面到底做了什麼事：

在介面層面列印入參資訊以及返回值就能定位到很多問題（懂的都懂），使用註解還不用干擾到我們正常的業務程式碼就能列印出這麼好的日誌資訊了（這個逼是裝上了）

它的實現原理並不複雜，感興趣的小夥伴可以拉程式碼自己看看，先看readmd再看程式碼！！

GitHub：https://github.com/qqxx6661/logRecord

總的來說，他通過SpEL表示式來讀取到#sendRequest入參物件的資訊，而註解解析則用的是Spring AOP。至於自定義上下文以及自定義函式我在這是沒用到的，至少在austin專案場景下，我感覺都沒什麼用。哦，對了，它還能將日誌輸出到別的管道（MQ）。可惜的是，我這場景也用不到。

在目前的實現下，我就只有這個介面能用到該元件，我承認他在某些場景是很好用。

但它是有侷限性的：列印的日誌資訊跟方法引數強相關：如果要列印方法引數以外的變數那需要用到上下文Context 或者自定義函式 。自定義函式的使用姿勢是有侷限性的，我們並不能把日誌所涉及的變數都抽取到某函式上。如果用上下文Context的話，還是得嵌入業務程式碼裡，那為啥不直接拼裝好日誌打呢？

我一度懷疑是不是我的使用姿勢不對，跟基友探討了下，我的應用場景下還得自己抽取LogUtils進行日誌列印。

02、資料鏈路追蹤

從上面的介面列印的日誌以及能很快地排查出接入層的問題了，其實重頭戲其實是在處理層上，回顧下處理層目前做的事情：

在處理層上會有不少的平臺過濾規則，這些過濾規則大多都不是針對於訊息模板的，而是針對於userId(接收者)的。在這個處理過程中，記錄下每個訊息模板中的每個使用者的執行情況就尤其重要了。

1、定位和排查問題。如果客戶反饋使用者收不到簡訊，一般情況下都在這個處理的過程中導致的（可能是被去重，可能是呼叫介面出問題）

2、對模板執行的整體鏈路資料分析。一個訊息模板一天傳送的量級，中途被每個規則過濾的量級，成功下發的量級以及訊息最後被點選的量級。除了點選資料，其他的資料都來源處理層

基於上面的背景，我設計了一套埋點的規則，在處理關鍵鏈路上打上對應的點位?

目前點位的資訊是不全的，隨著系統的完善和接入各個渠道，這裡的點位資訊還會繼續增加，只要我們認為有哪些地方是需要記錄下來的，就可以增加。

可能看到這裡你會覺得有些抽象，我請求一次介面列印下日誌就容易懂啦：

// 1、接入層列印日誌（returnStr列印處理結果，而msg列印出入參資訊）
2022-01-08 15:44:53.512 [http-nio-8080-exec-7] INFO  com.java3y.austin.utils.LogUtils - 
{"bizId":"1","bizType":"SendService#send","logId":"34df87fc-0489-46c1-b39f-cafd7652f55b",
"msg":"{\"code\":\"send\",\"messageParam\":{\"extra\":null,\"receiver\":\"13288888888\",\"variables\":{\"title\":\"yyyyyy\",\"contentValue\":\"66661641627893157\"}},\"messageTemplateId\":1}","operateDate":1641627893512,"returnStr":"{\"code\":\"00000\",\"msg\":\"操作成功\"}","success":true,"tag":"operation"}

// 2、處理層列印入口日誌（表示成功消費到Kafka的訊息 state=10）
2022-01-08 15:44:53.622 [org.springframework.kafka.KafkaListenerEndpointContainer#6-0-C-1] INFO  com.java3y.austin.utils.LogUtils - 
{"businessId":1000000120220108,"ids":["13288888888"],"state":10,"timestamp":1641627893622}

// 3、處理層列印入口日誌（表示成功消費到Kafka的原始日誌）
2022-01-08 15:44:53.622 [org.springframework.kafka.KafkaListenerEndpointContainer#6-0-C-1] INFO  com.java3y.austin.utils.LogUtils - 
{"bizType":"Receiver#consumer","object":{"businessId":1000000120220108,"contentModel":{"content":"66661641627893157"},"deduplicationTime":1,"idType":30,"isNightShield":0,"messageTemplateId":1,"msgType":10,"receiver":["13288888888"],"sendAccount":66,"sendChannel":30,"templateType":10},"timestamp":1641627893622}

// 4、處理層列印邏輯過濾日誌（state=20，表示這條訊息由於配置了丟棄，已經丟棄掉）
2022-01-08 15:44:53.623 [pool-8-thread-3] INFO  com.java3y.austin.utils.LogUtils - 
{"businessId":1000000120220108,"ids":["13288888888"],"state":20,"timestamp":1641627893622}

我列印日誌的核心邏輯是：

在入口側（這裡包括介面的入口以及剛消費Kafka的入口）需要列印出原始的資訊。原始資訊有了，才好對問題進行定位和排查，至少幫助我們復現
在處理過程中使用某個標識來標明處理的過程（10代表成功消費Kafka，20代表該訊息已經被丟棄...)，並且日誌的格式是統一的這樣後續我們可以統一清洗該日誌資訊