騰訊 tRPC-Go 教學——（5）filter、context 和日誌元件

發表於2024-03-04
TrpcGoFilterContext元件

本文我們們來介紹一下在 tRPC 中的 filter 機制、context 用法，以及在相關機制上可以實現的 tracing log 能力。

說實話，這一部份是我個人最不喜歡的 tRPC 的實現模式，不過這不妨礙我們們使用它——只要把它封裝成讓人更為舒服的模式也未嘗不可。

系列文章

tracelog 程式碼簡介

本文所涉及的內容，都可以使用筆者的一個 tracelog package 來作輔助講解。這個包所提供的功能有：

  1. 基於 tRPC context 和 message 機制 (下文說明)，在日誌中包含 trace ID 資訊便於跟蹤一個呼叫鏈
  2. 基於 tRPC filter 機制，跨微服務傳遞 trace ID 並自動實現 1
  3. 透過日誌記錄每次主調和被調的整體情況

具體的實現方法，本文放在最後，等講完涉及的 tRPC 機制之後再作說明。

filter 機制

在 gRPC 中，實現了攔截器 interceptor 功能；類似的在著名的 HTTP 框架 gin 中，也提供了中介軟體模式。這兩種機制的功能非常類似，都是在作為 server 時收到請求、以及作為 client 時傳送請求時，優先對資料進行一些處理、檢查等邏輯，非常適合用來做一些非業務邏輯，比如：

  • 介面鑑權
  • 日誌記錄
  • 監控上報
  • ……

在 tRPC 中，類似的機制被稱為 filter 過濾器 / 攔截器。在 gRPC 中 interceptor 有四種，但 tRPC 中簡化為 server filter 和 client filter 兩種。

我們可以參考 tracelog filter.go 檔案的 RegisterTraceLogFilter 函式。該函式向 tRPC 框架註冊了一個名為 tracelog (參見 tracelog.FilterName 常量) 的 filter，包含 server filter 和 client filter。

函式格式

其中 server filter 回撥的格式為:

func(ctx context.Context, req any, next filter.ServerHandleFunc) (rsp any, err error)

而 client filter 為:

func(ctx context.Context, req, rsp any, next filter.ClientHandleFunc) error

實現

在 filter 函式中，我們可以撰寫程式碼觀察當前的呼叫情況。不論是 server 還是 client filter 函式，都包含一個 next 引數。類似於 gRPC 的 interceptor 機制，tRPC 也是使用類似於堆疊形式組織各 filter 的，對於每一個 filter 函式，應當將 next 視作真正的業務處理邏輯。在 next 之前處理業務前置邏輯，在 next 之後撰寫業務後置邏輯。

比如最簡單的例子——列印一下耗時日誌:

func clientFilter(ctx context.Context, req, rsp any, next filter.ClientHandleFunc) error {
    start := time.Now()
    err := next(ctx, req, rsp)
    log.DebugContextf(ctx, "ela: %v, err: %v", time.Since(start), err)
    return err
}

filter.Register 函式所傳遞的兩個 filter 函式均不應為空，如果 filter 邏輯就是透傳即可，那麼就簡單實現:

func emptyServerFilter(ctx context.Context, req any, next filter.ServerHandleFunc) (any, error) {
    return next(ctx, req)
}

tRPC 也內建了一些常用的 filter，匯入方式為:

import _ "trpc.group/trpc-go/trpc-filter/$(filter_name)"

實際的倉庫地址為: github.com/trpc-ecosystem/go-filter

其中我們在業務中必備的 filter 是 recovery，防止業務邏輯 panic 導致服務重啟。其他的比如 debuglog 和 validation 我們也用，但相對少。讀者可以查閱文件後再選用。

filter 配置

可以看到，filter 分 server 側和 client 側。首先在程式碼中需要匯入相關的包，從而在二進位制中支援相關能力。目前大部分官方預設的 filter 是透過 init 函式的方式註冊到 trpc 框架中的。

讓我們以前文給出的幾個服務作為例子，配置方式是在 trpc_go.yaml 的 server 和 client 側各有一個名為 filter 的字串陣列型別的欄位，我們可以將 filter 按名稱配置在此處，分別對應 server filter 和 client filter，此處的配置對所有的 server / client 生效。請注意，filter 配置的順序也會影響 trpc 框架呼叫 filter 的順序。

context 和 "message"

從 Go 1.13 版開始，以 net/http 包的 NewRequestWithContext 函式為標誌，開始全面支援 context 機制。gRPC 很快跟進，在所有 client 和 server 端的實現上，均包含 ctx 引數。作為後浪的 tRPC，也繼承了這一特性。

超時控制

在 tRPC 中有多個超時配置。我們以之前的文章中提過的 http-auth-server 的 trpc_go.yaml 檔案為例:

server:
  timeout: 2000
  service:
    - name: demo.httpauth.Auth
      nic: eth0
      port: 8001
      network: tcp
      protocol: http
      timeout: 1800

client:
  timeout: 3000
  service:
    - name: demo.account.User
      target: ip://127.0.0.1:8002
      network: tcp
      protocol: trpc
      timeout: 1000

在上述配置檔案中的超時時間單位均為毫秒，分別有:

配置項說明
server.service[n].timeout具體 server 端的處理超時時間
server.timeout當上一配置缺失時，所對應的預設超時時間
client.service[n].timeout發起一個 client 呼叫的超時時間
client.timeout當上一配置缺失時，所對應的預設超時時間

其次，下文中會提及 tRPC 的 metadata，而 tRPC 發起呼叫的時候，超時時間也會透過 metadata 的形式往下進一步傳遞。如果你的上游服務也是 tRPC 的話，那麼要注意：超時時間還可能受到上游的限制。

此外，開發者也可以在程式碼中顯式地為 context 設定一個超時時間，比如透過 WithTimeout 和 WithDeadline 函式，獲得一個附帶超時時間的 context，傳遞給 tRPC 框架用於發起主調。

這麼多的超時時間，到底取哪一個呢？

  • 答：tRPC 框架在呼叫 server 端業務程式碼，以及發起 client 主調時，均會選擇上述超時時間中最短的一個。

codec.Msg

在 tRPC 中對 context 的使用邏輯，請參見程式碼的 codec 包實現。tRPC 使用 codec 包，提供了擴充套件任意第三方編碼格式的能力。

如果讀者需要實現除了預設支援的幾種協議之外的其他編解碼格式（比如騰訊 tars 所使用的 jce），可以閱讀相關的 README 並進行實現。不過對於本文而言，我們更關注 tRPC 使用 message 功能所提供的更多能力。所謂的 "message"，指的是 codec.Msg 介面型別，讀者可以檢視這個介面的實現。

正如前文所述，tRPC 的所有 server 端方法中，第一個函式均為 context.Context 型別，而 tRPC 基於 context 的 WithValue 方法，內建了 codec.Msg 型別資料。只要你的 server 方法是透過 tRPC 框架呼叫的，那麼開發者均可以使用 codec.EnsureMessage 函式，從 context 中提取出 Msg 例項。

Msg 介面的功能很多，讀者可以一一瞭解。本文我們只介紹 Msg 的其中幾個最常用的功能：

  • metadata
  • 超時機制
  • 日誌器和 tracing

日誌

在 tRPC 中，日誌的 tracing（跟蹤）主要是透過在寫入日誌時，額外新增若干的資訊。tRPC 的 log 底層呢是使用 zap 來實現的，不過 zap 雖然是結構化的日誌，但是 tRPC 暴露出來的實際上更多的是非結構化的日誌介面。

功能

以 INFO 級別為例，tRPC 有四種日誌函式格式:

log.Info(xxx, xxx...)
log.Infof("format", xxx...)
log.InfoContext(ctx, xxx, xxx...)
log.InfoContextf(ctx, "format", xxx...)

其中 log.Info 的輸出效果類似於 fmt.Print 函式，而 log.Infof 則類似於 fmt.Printf。而帶 ctx 引數的另外兩個函式，則可以在前面兩個日誌函式的基礎上，輸出在 ctx 中攜帶的一些額外資訊。往往我們可以在 ctx 中給 tRPC 的日誌器攜帶 tracing 資料，此時利用帶 ctx 的日誌函式就可以列印出這些資料了。

至於如何攜帶資訊，我們在本文最後關於 tracelog 的實現中再作說明。

Fatal 級別日誌

在 tRPC 中，日誌的級別從低到高分別是: TRACE、DEBUG、INFO、WARN、ERROR、FATAL。其中 trace 級別在實際業務中非常少用。

Fatal 級別的日誌比較特殊，它會先完成日誌的輸出，然後再退出服務。如果在業務中遇到了某些導致服務無法執行下去的情況，我們不使用 panic 函式，而是使用 log.Fatal 系列呼叫，保留足夠的現場資訊之後再退出服務。

配置

tRPC 日誌的 官方文件，個人覺得是一眾 tRPC 文件中最詳盡和清晰的文件之一了。簡單而言，就是開發者只要配置 trpc_go.yaml 中的 plugins.log.default 中的相關欄位就可以了。我個人常用的配置如下：

plugins:
  log:
    default:
      - writer: console
        level: fatal       # 標準輸出我一般就不打日誌了, 只保留嚴重異常
        formatter: console
      - writer: file
        level: debug       # 本地檔案的日誌級別看情況, 除錯 / 測試用 debug, 正常線上環境用 info, 如果日誌量太大則使用 warn 或 error
        formatter: json    # 檔案日誌我喜歡用 JSON, 便於各種日誌採集器採集
        formatter_config:  # 格式化配置
          time_fmt: 2006-01-02 15:04:05  # 日期格式化, 與 go time 的格式化格式相同
          time_key: time   # 日誌時間欄位名稱，不填預設"T"，填 "none" 可禁用此欄位
          level_key: level # 日誌級別欄位名稱，不填預設"L"，填 "none" 可禁用此欄位
          name_key: none   # 日誌名稱欄位名稱，不填預設"N"，填 "none" 可禁用此欄位
          caller_key: caller   # 日誌呼叫方欄位名稱，不填預設"C"，填 "none" 可禁用此欄位
          message_key: message # 日誌訊息體欄位名稱，不填預設"M"，填 "none" 可禁用此欄位
          stacktrace_key: stack_trace  # 日誌堆疊欄位名稱，不填預設"S"，填 "none" 可禁用此欄位
        writer_config:
          log_path: ./log/   # 表示日誌放在哪個目錄下
          filename: trpc.log # 表示日誌檔案的基礎名稱
          write_mode: 2      # 日誌寫入模式，1-同步，2-非同步，3-極速 (非同步丟棄), 不配置預設非同步模式
          roll_type: size    # 檔案滾動型別，time 為按時間滾動, size 表示按檔案大小滾動
          max_size: 1000     # 單位: MB
          max_backups: 10    # 最大日誌檔案數, 超出則自動刪除

更詳細的欄位說明請參照 官方文件。

metadata

在 gRPC 中，透過 incoming metadata 和 outgoing metadata 的機制，可以在請求 / 響應包體資料之外，額外傳輸與業務不直接相關的後設資料。

在 tRPC 中，則使用 server metadata 的機制進行傳遞（還有一個 client metadata，但是筆者沒有完全把握其日常用法，就暫時不講了）。tRPC 的 metadata 也是基於 codec.Msg 介面進行封裝的，但是業務開發者可以不需要太關注這個 feature，感興趣的話再仔細研究就可以了。

實際應用中，metadata 一般是用來承載非業務資料，比如說可觀測性引數、資料埋點、使用者畫像、標籤、染色資訊等等，而不是具體某個業務的邏輯資料。

個人不建議在業務邏輯中直接操作 metadata，業務程式碼專注做業務邏輯就行了。至於 metadata 的操作方式，可以透過 filter 機制來實現。只要上下游都是 trpc，那麼 metadata 都能夠很順暢地傳輸。

tracelog 的實現邏輯

上面我們瞭解完了基礎知識，可能讀者還是覺得有點懵。沒關係，讓我們來看看全文作為實際例子的 tracelog 是如何實現的。筆者的這個 tracelog 工具，思路借鑑了我所在團隊所開發的的一個同名 filter，但是在實現上完全不同。

trace ID

在 tracelog 中實現 trace ID 的邏輯可參見 tracelog.go 檔案。筆者將 trace ID 視為一組堆疊式的欄位，每一級棧可以一層一層地追加 trace ID，從而在不同高度或層面上進行 tracing——這就是在設計理念上與筆者所在團隊的實現完全不同的一個點，這種模式非常適合單體服務，這是另一個大課題了，筆者以後再講哈。

至於如何將自定義的 trace ID 新增到日誌器中，請讀者參考筆者的 cloneCtxAndGenerateLog() 函式即可。從這個函式中可以看到，每當新增一個 tracing 欄位的時候，tRPC 會新建一個 logger。這也是筆者認為不太妥當的一點：這個模式太重了。但是框架如此，也沒辦法。

server filter

tracelog 的 filter 程式碼請參見 filter.go。讓我們先來看一下 server filter，該 filter 的功能有兩個：

  1. 如果有的話，從 metadata 中提取出 trace ID；如果沒有的話，用雪花演算法生成一個並存入 ctx 中
  2. 在日誌中列印出 server 端執行情況，包括入參、header、metadata、響應、錯誤等資訊。

其中 1，呼叫的是前文提到的 Msg 型別的 ServerMetaData 來獲得 metadata。

至於 2，請讀者實際看 函式實現 更加直觀。

client filter

client 實現的邏輯其實也跟 server 側類似：

  1. 如果有 trace ID，則放入 metadata
  2. 在日誌中列印出 client 端執行情況，包括入參、header、metadata、響應、錯誤等資訊。

使用

我們參照前文的說明，在 配置 中加上 tracelog filter 以及日誌相關配置。前面我們提到的 http-auth-server 和 user 兩個服務都配置上。然後，按照之前我們提到的方法啟動兩個服務。

然後我們傳送命令: curl '127.0.0.1:8001/demo/auth/Login?username=amc'。

因為沒有指定密碼，所以我們還是正常獲得錯誤響應: {"err_code":404,"err_msg":"密碼錯誤"}。

錯誤不重要，本文我們要看的是日誌。我們來看看在這個配置下自動生成的日誌檔案: log/trpc.log。我們看 http-auth-server 的日誌檔案。可以看到，檔案的每一行就是一個 JSON 資料。我們取剛才的請求產生的日誌來看：

{"level":"INFO","time":"2024-03-04 02:19:28","caller":"server/service.go:167","message":"process:1016, http service:demo.httpauth.Auth launch success, tcp:127.0.0.1:8001, serving ..."}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"tracelog/filter.go:107","message":"{\"callee\":\"unknown\",\"http_req\":&{GET /demo/auth/Login?username=amc HTTP/1.1 1 1 map[Accept:[*/*] User-Agent:[curl/7.68.0]] {} <nil> 0 [] false 127.0.0.1:8001 map[] map[] <nil> map[] 127.0.0.1:39774 /demo/auth/Login?username=amc <nil> <nil> <nil> 0xc000279b00 <nil> [] map[]},\"server_metadata\":{\"trace_id_stack\":\"WyJjYXN5cDdwOXpiNCJd\"},\"req\":{\"username\":\"amc\"},\"req_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/user.*GetAccountByUserNameRequest\",\"rsp\":{\"err_msg\":\"success\",\"user_id\":\"1\",\"username\":\"amc\",\"password_hash\":\"8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92\"},\"rsp_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/user.*GetAccountByUserNameResponse\",\"cost\":\"303.230671ms\"}","trace_id":"casyp7p9zb4"}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"service/http_auth_service.go:50","message":"請求的密碼為: , 實際密碼為 8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92","trace_id":"casyp7p9zb4"}
{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"tracelog/filter.go:63","message":"{\"caller\":\"unknown\",\"http_req\":&{GET /demo/auth/Login?username=amc HTTP/1.1 1 1 map[Accept:[*/*] User-Agent:[curl/7.68.0]] {} <nil> 0 [] false 127.0.0.1:8001 map[] map[] <nil> map[] 127.0.0.1:39774 /demo/auth/Login?username=amc <nil> <nil> <nil> 0xc000279b00 <nil> [] map[]},\"server_metadata\":null,\"req\":{\"username\":\"amc\"},\"req_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/httpauth.*LoginRequest\",\"rsp\":{\"err_code\":404,\"err_msg\":\"密碼錯誤\"},\"rsp_type\":\"github.com/Andrew-M-C/trpc-go-demo/proto/httpauth.*LoginResponse\",\"cost\":\"303.953412ms\"}","trace_id":"casyp7p9zb4"}

呃，太長了……取一條短的吧：

{"level":"DEBUG","time":"2024-03-04 02:19:32","caller":"service/http_auth_service.go:50","message":"請求的密碼為: , 實際密碼為 8d969eef6ecad3c29a3a629280e686cf0c3f5d5a86aff3ca12020c923adc6c92","trace_id":"casyp7p9zb4"}

可以清晰地看到，這一行日誌輸出了級別、時間、日誌呼叫方資訊、日誌正文。此外，還有一個名為 trace_id 的欄位，這就是 tracelog 自動生成並插入的效果。

下一步

本文相比前面的文章而言雜了很多，主要是涉及的內容相互強耦合，所以我把他們都放在同一篇文章裡。推薦讀者還是儘量動手實驗把這些功能跑一遍，能夠在實際開發中更好地理解 tPPC 的這些 feature，這是自己開發 filter 的重要基礎知識。

下一篇文章我們來學習一下 tRPC 的名字服務、服務發現和定址相關的功能吧。筆者還是會盡量把這系列堅持下去的💪

參考閱讀

本文章採用 知識共享署名-非商業性使用-相同方式共享 4.0 國際許可協議 進行許可。

原作者： amc，原文釋出於騰訊雲開發者社群，也是本人的部落格。歡迎轉載，但請註明出處。

原文標題：《騰訊 tRPC-Go 教學——（5）filter、context 和日誌元件》

釋出日期：2024-03-04

原文連結：https://cloud.tencent.com/developer/article/2393468。

CC BY-NC-SA 4.0 DEED.png

相關文章