現在微服務架構盛行，很多以前的單體應用服務都被拆成了多個分布式的微服務，以解決應用系統發展壯大後的開發周期長、難以擴充、故障隔離等挑戰。
不過技術領域有個諺語叫--沒有銀彈，這句話的意思其實跟現實生活中任何事都有利和弊兩面一樣，意思是告訴我們不要寄希望于用一個解決方案解決所有問題，引入新方案解決舊問題的同時，勢必會引入新的問題。典型的比如，原本在單體應用裡可以靠本地資料庫的ACID 事務來保證資料一緻性。但是微服務拆分後，就沒那麼簡單了。
同理拆分成為服務後，一個業務邏輯的完成一般需要多個服務的協作才能完成，每個服務都會有自己的業務日志，那怎麼把各個服務的業務日志串聯起來，也會變難，今天我們就聊一下微服務的日志串聯的方案。
在早前的文章分布式鍊路跟蹤中的traceid和spanid代表什麼？ 裡我給大家介紹過 TraceId 和 SpanId 的概念
圖檔
- trace 是請求在分布式系統中的整個鍊路視圖
- span 則代表整個鍊路中不同服務内部的視圖，span 組合在一起就是整個 trace 的視圖
在微服務的日志串聯裡，我們同樣能使用這兩個概念，通過 trace 串聯出一個業務邏輯的所有業務日志，span 串聯出在單個服務裡的業務日志。
而單個微服務的日志串聯的時候還有個挑戰是怎麼把資料庫執行過程的一些日志也注入這些 traceid 和 spanid 打到業務日志裡。下面我們就分别通過
- HTTP 服務間的日志追蹤參數傳遞
- HTTP 和 RPC 服務間的追蹤參數傳遞
- ORM 的日志中注入追蹤參數
來簡述一下微服務業務日志串聯的思路。提前聲明本文中給出的解決方案更多是 Go 技術棧的，其他語言的技術棧有些方案實作跟這裡列舉的稍有不同，尤其是 Java 一些開源庫上比較容易實作的東西在 Go 這裡并不簡單。
其實如果使用 APM 的話，是有比較統一的解決方案的，比如接入 Skywalking 就可以，不過還是有額外的學習成本以及需要引入外部系統元件的。
HTTP 服務間的日志追蹤參數傳遞
HTTP 服務間的追蹤參數傳遞，主要是靠在全局的路由中間件來搞，我們可以在請求頭裡指定 TraceId 和 SpanId。當然如果是請求到達的第一個服務，則生成 TraceId 和 SpanId，加到Header 裡往下傳。
type Middleware func(http.HandlerFunc) http.HandlerFunc
func withTrace() Middleware {
// 建立中間件
return func(f http.HandlerFunc) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
traceID := r.Header.Get("xx-tranceid")
parentSpanID := r.Header.Get("xx-spanid")
spanID := genSpanID(r.RemoteAddr)
if traceID == "" {// traceID為空，證明是初始調用，讓root span id == trace id
traceId = spanID
}
// 把 追蹤參數通過 Context 在服務内部進行中傳遞
ctx := context.WithValue(r.Context(), "trace-id", traceID)
ctx := context.WithValue(ctx, "pspan-id", parentSpanID)
ctx := context.WithValue(ctx, "span-id", spanID)
r.WithContext(ctx)
// 調用下一個中間件或者最終的handler處理程式
f(w, r)
}
}
}
複制
上面主要通過在中間件程式，擷取 Header 頭裡存儲的追蹤參數，把參數儲存到請求的 Context 中在服務内部傳遞。上面的程式有幾點需要說明：
- genSpanID 是根據遠端用戶端IP 生成唯一 spanId 的方法，生成方法隻要保證哈希串唯一就行。
- 如果服務是請求的開始，在生成spanId 的時候，我們把它也設定成 traceId，這樣就能通過 spanId == traceId 判斷出目前的 Span 是請求的開端、即 root span。
接下來往下遊服務發起請求的時候，我們需要在把 Context 裡存放的追蹤參數，放到 Header 裡接着往下個 HTTP 服務傳。
func HttpGet(ctx context.Context url string, data string, timeout int64) (code int, content string, err error) {
req, _ := http.NewRequest("GET", url, strings.NewReader(data))
defer req.Body.Close()
req.Header.Add("xx-traceid", ctx.Value("trace-id").(string))
req.Header.Add("xx-spanid", ctx.Value("span-id").(string))
client := &http.Client{Timeout: time.Duration(timeout) * time.Second}
resp, error := client.Do(req)
}
複制
HTTP 和 RPC 服務間的追蹤參數傳遞
上面咱們說的上下遊服務都是 HTTP 服務的追蹤參數傳遞，那如果是 HTTP 服務的下遊是 RPC 服務呢？
其實跟發HTTP請求可以配置HTTP用戶端攜帶 Header 和 Context 一樣，RPC用戶端也支援類似功能。以 gRPC 服務為例，用戶端調用RPC 方法時，在可以攜帶的中繼資料裡設定這些追蹤參數。
traceID := ctx.Value("trace-id").(string)
traceID := ctx.Value("span-id").(string)
md := metadata.Pairs("xx-traceid", traceID, "xx-spanid", spanID)
// 建立一個有 metadata 的 context
ctx := metadata.NewOutgoingContext(context.Background(), md)
// 單向的 Unary RPC
response, err := client.SomeRPCMethod(ctx, someRequest)
複制
RPC 的服務端的處理方法裡，可以再通過 metadata 把中繼資料裡存儲的追蹤參數取出來。
func (s server) SomeRPCMethod(ctx context.Context, req *xx.someRequest) (reply *xx.SomeReply, err error) {
remote, _ := peer.FromContext(ctx)
remoteAddr := remote.Addr.String()
// 生成本次請求在目前服務的 spanId
spanID := utils.GenerateSpanID(remoteAddr)
traceID, pSpanID := "", ""
md, _ := metadata.FromIncomingContext(ctx)
if arr := md["xx-tranceid"]; len(arr) > 0 {
traceID = arr[0]
}
if arr := md["xx-spanid"]; len(arr) > 0 {
pSpanID = arr[0]
}
return
}
複制
有一個概念我們需要注意一下，代碼裡是把上遊傳過來的 spanId 作為本服務的 parentSpanId 的，本服務處理請求時候的 spanId 是需要重新生成的，生成規則在之前我們介紹過。
除了 HTTP 網關調用 RPC 服務外，處理請求時也經常出現 RPC 服務間的調用，那這種情況該怎麼弄呢？
RPC 服務間的追蹤參數傳遞
其實跟 HTTP 服務調用 RPC 服務情況類似，如果上遊也是 RPC 服務，那麼則應該在接收到的上層中繼資料的基礎上再附加的中繼資料。
md := metadata.Pairs("xx-traceid", traceID, "xx-spanid", spanID)
mdOld, _ := metadata.FromIncomingContext(ctx)
md = metadata.Join(mdOld, md)
ctx = metadata.NewOutgoingContext(ctx, md)
複制
當然如果我們每個用戶端調用和RPC 服務方法裡都這麼搞一遍得類似，gRPC 裡也有類似全局路由中間件的概念，叫攔截器，我們可以把追蹤參數傳遞這部分邏輯封裝在用戶端和服務端的攔截器裡。
gRPC 攔截器的詳細介紹請看我之前的文章 -- gRPC生态裡的中間件
用戶端攔截器
func UnaryClientInterceptor(ctx context.Context, ... , opts ...grpc.CallOption) error {
md := metadata.Pairs("xx-traceid", traceID, "xx-spanid", spanID)
mdOld, _ := metadata.FromIncomingContext(ctx)
md = metadata.Join(mdOld, md)
ctx = metadata.NewOutgoingContext(ctx, md)
err := invoker(ctx, method, req, reply, cc, opts...)
return err
}
// 連接配接伺服器
conn, err := grpc.Dial(*address, grpc.WithInsecure(),grpc.WithUnaryInterceptor(UnaryClientInterceptor))
複制
服務端攔截器
func UnaryServerInterceptor(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
remote, _ := peer.FromContext(ctx)
remoteAddr := remote.Addr.String()
spanID := utils.GenerateSpanID(remoteAddr)
// set tracing span id
traceID, pSpanID := "", ""
md, _ := metadata.FromIncomingContext(ctx)
if arr := md["xx-traceid"]; len(arr) > 0 {
traceID = arr[0]
}
if arr := md["xx-spanid"]; len(arr) > 0 {
pSpanID = arr[0]
}
// 把 這些ID再搞到 ctx 裡，其他兩個就省略了
ctx := Context.WithValue(ctx, "traceId", traceId)
resp, err = handler(ctx, req)
return
}
複制
ORM 的日志中注入追蹤參數
其實，如果你用的是 GORM 注入這個參數是最難的，如果你是 Java 程式員的話，可能會對比如阿裡巴巴的 Druid 資料庫連接配接池加入類似 traceId 這種參數習以為常，但是 Go 的 GORM 庫确實做不到，也有可能新版本可以，我用的還是老版本，其他 Go 的 ORM 庫沒有接觸過，知道的同學可以留言給我們普及一下。
GORM做不到在日志裡加入追蹤參數的原因就是這個GORM 的 logger 沒有實作SetContext方法，是以除非修改源碼中調用db.slog的地方，否則無能為力。
不過話也不能說死，之前介紹過一種使用函數調用棧實作 Goroutine Local Storage 的庫 jtolds/gls ，我們可以通過它在外面封裝一層來實作，并且還需要重新實作 GORM Logger 的列印日志的 Print 方法。
下面大家感受一下，GLS 庫的使用，确實有點點怪，不過能過。
func SetGls(traceID, pSpanID, spanID string, cb func()) {
mgr.SetValues(gls.Values{traceIDKey: traceID, pSpanIDKey: pSpanID, spanIDKey: spanID}, cb)
}
gls.SetGls(traceID, pSpanID, spanID, func() {
data, err = findXXX(primaryKey)
})
複制
重寫 Logger 的我就簡單貼貼，核心思路還是在記錄SQL到日志的時候，從調用棧裡把 traceId 和 spanId 取出來放一并加入到日志記錄裡。
// 對Logger 注冊 Print方法
func (l logger) Print(values ...interface{}) {
if len(values) > 1 {
// ...
l.sqlLog(sql, args, duration, path.Base(source))
} else {
err := values[2]
log.Error("source", source, "err", err)
}
}
}
func (l logger) sqlLog(sql string, args []interface{}, dur time.Duration, source string) {
argsArr := make([]string, len(args))
for k, v := range args {
argsArr[k] = fmt.Sprintf("%v", v)
}
argsStr := strings.Join(argsArr, ",")
spanId := gls.GetSpanId()
traceId := gls.GetTraceId()
//對于逾時的,統一打warn日志
if dur > (time.Millisecond * 500) {
log.Warn("xx-traceid", traceId, "xx-spanid", spanId, "sql", sql, "args_detal", argsStr, "source", source)
} else {
log.Debug("xx-traceid", traceId, "xx-spanid", spanId, "sql", sql, "args_detal", argsStr, "source", source)
}
}
複制
通過調用棧擷取 spanId 和 traceId 的是類似這樣的方法，由 GLS 庫提供的方法封裝實作。
// Get spanID 用于Goroutine的鍊路追蹤
func GetSpanID() (spanID string) {
span, ok := mgr.GetValue(spanIDKey)
if ok {
spanID = span.(string)
}
return
}
複制
日志列印的話，也是對超過 500 毫秒的SQL執行進行 Warn 級别日志的列印，友善線上環境分析問題，而其他的SQL執行記錄，因為使用了 Debug 日志級别隻會在測試環境上顯示。
總結
用分布式鍊路追蹤參數串聯起整個服務請求的業務日志，線上上的分布式環境中是非常有必要的，其實上面隻是簡單闡述了一些思路，隻有把日志搞的足夠好，上下文資訊足夠多才會能高效地定位出線上問題。感覺這部分細節太多，想用一篇文章闡述明白非常困難。
而且還有一點就是日志錯誤級别的選擇也非常有講究，如果本該用Debug的地方，用了 Info 級别，那線上日志就會出現非常多的幹擾項。
細節的地方怎麼實作，就屬于實踐的時候才能把控的了。希望這篇文章能給你個實作分布式日志追蹤的主旨思路。