現(xiàn)在微服務架構盛行，很多以前的單體應用服務都被拆成了多個分布式的微服務，以解決應用系統(tǒng)發(fā)展壯大后的開發(fā)周期長、難以擴展、故障隔離等挑戰(zhàn)。

不過技術領域有個諺語叫--沒有銀彈，這句話的意思其實跟現(xiàn)實生活中任何事都有利和弊兩面一樣，意思是告訴我們不要寄希望于用一個解決方案解決所有問題，引入新方案解決舊問題的同時，勢必會引入新的問題。典型的比如，原本在單體應用里可以靠本地數(shù)據(jù)庫的ACID 事務來保證數(shù)據(jù)一致性。但是微服務拆分后，就沒那么簡單了。

同理拆分成為服務后，一個業(yè)務邏輯的完成一般需要多個服務的協(xié)作才能完成，每個服務都會有自己的業(yè)務日志，那怎么把各個服務的業(yè)務日志串聯(lián)起來，也會變難，今天我們就聊一下微服務的日志串聯(lián)的方案。

image.png

trace 是請求在分布式系統(tǒng)中的整個鏈路視圖

span 則代表整個鏈路中不同服務內部的視圖，span 組合在一起就是整個 trace 的視圖

在微服務的日志串聯(lián)里，我們同樣能使用這兩個概念，通過 trace 串聯(lián)出一個業(yè)務邏輯的所有業(yè)務日志，span 串聯(lián)出在單個服務里的業(yè)務日志。

而單個微服務的日志串聯(lián)的時候還有個挑戰(zhàn)是怎么把數(shù)據(jù)庫執(zhí)行過程的一些日志也注入這些 traceid 和 spanid 打到業(yè)務日志里。下面我們就分別通過

HTTP 服務間的日志追蹤參數(shù)傳遞

HTTP 和 RPC 服務間的追蹤參數(shù)傳遞

ORM 的日志中注入追蹤參數(shù)

來簡述一下微服務業(yè)務日志串聯(lián)的思路。提前聲明本文中給出的解決方案更多是 Go 技術棧的，其他語言的技術棧有些方案實現(xiàn)跟這里列舉的稍有不同，尤其是 Java 一些開源庫上比較容易實現(xiàn)的東西在 Go 這里并不簡單。

其實如果使用 APM 的話，是有比較統(tǒng)一的解決方案的，比如接入 Skywalking 就可以，不過還是有額外的學習成本以及需要引入外部系統(tǒng)組件的。

HTTP 服務間的日志追蹤參數(shù)傳遞
HTTP 服務間的追蹤參數(shù)傳遞，主要是靠在全局的路由中間件來搞，我們可以在請求頭里指定 TraceId 和 SpanId。當然如果是請求到達的第一個服務，則生成 TraceId 和 SpanId，加到Header 里往下傳。

type Middleware func(http.HandlerFunc) http.HandlerFunc

func withTrace() Middleware {
    // 創(chuàng)建中間件
    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
          }
            // 把 追蹤參數(shù)通過 Context 在服務內部處理中傳遞
           ctx := context.WithValue(r.Context(), "trace-id", traceID)
           ctx := context.WithValue(ctx, "pspan-id", parentSpanID)
           ctx := context.WithValue(ctx, "span-id", parentSpanID)
           r.WithContext(ctx)

            // 調用下一個中間件或者最終的handler處理程序
            f(w, r)
        }
    }
}

上面主要通過在中間件程序，獲取 Header 頭里存儲的追蹤參數(shù)，把參數(shù)保存到請求的 Context 中在服務內部傳遞。上面的程序有幾點需要說明：

genSpanID 是根據(jù)遠程客戶端IP 生成唯一 spanId 的方法，生成方法只要保證哈希串唯一就行。

如果服務是請求的開始，在生成spanId 的時候，我們把它也設置成 traceId，這樣就能通過 spanId == traceId 判斷出當前的 Span 是請求的開端、即 root span。

接下來往下游服務發(fā)起請求的時候，我們需要在把 Context 里存放的追蹤參數(shù)，放到 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-trace-tid", ctx.Value("trace-id").(string))
    req.Header.Add("xx-trace-tid", ctx.Value("span-id").(string))
  
    client := &http.Client{Timeout: time.Duration(timeout) * time.Second}
    resp, error := client.Do(req)
}

HTTP 和 RPC 服務間的追蹤參數(shù)傳遞
上面咱們說的上下游服務都是 HTTP 服務的追蹤參數(shù)傳遞，那如果是 HTTP 服務的下游是 RPC 服務呢？

其實跟發(fā)HTTP請求可以配置HTTP客戶端攜帶 Header 和 Context 一樣，RPC客戶端也支持類似功能。以 gRPC 服務為例，客戶端調用RPC 方法時，在可以攜帶的元數(shù)據(jù)里設置這些追蹤參數(shù)。

traceID := ctx.Value("trace-id").(string)
traceID := ctx.Value("trace-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 把元數(shù)據(jù)里存儲的追蹤參數(shù)取出來。

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 是需要重新生成的，生成規(guī)則在之前我們介紹過。

除了 HTTP 網(wǎng)關調用 RPC 服務外，處理請求時也經(jīng)常出現(xiàn) RPC 服務間的調用，那這種情況該怎么弄呢？

RPC 服務間的追蹤參數(shù)傳遞
其實跟 HTTP 服務調用 RPC 服務情況類似，如果上游也是 RPC 服務，那么則應該在接收到的上層元數(shù)據(jù)的基礎上再附加的元數(shù)據(jù)。

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 里也有類似全局路由中間件的概念，叫攔截器，我們可以把追蹤參數(shù)傳遞這部分邏輯封裝在客戶端和服務端的攔截器里。

gRPC 攔截器的詳細介紹請看我之前的文章 --gRPC生態(tài)里的中間件

客戶端攔截器

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 的日志中注入追蹤參數(shù)
其實，如果你用的是 GORM 注入這個參數(shù)是最難的，如果你是 Java 程序員的話，可能會對比如阿里巴巴的 Druid 數(shù)據(jù)庫連接池加入類似 traceId 這種參數(shù)習以為常，但是 Go 的 GORM 庫確實做不到，也有可能新版本可以，我用的還是老版本，其他 Go 的 ORM 庫沒有接觸過，知道的同學可以留言給我們普及一下。

GORM做不到在日志里加入追蹤參數(shù)的原因就是這個GORM 的 logger 沒有實現(xiàn)SetContext方法，所以除非修改源碼中調用db.slog的地方，否則無能為力。

不過話也不能說死，之前介紹過一種使用函數(shù)調用棧實現(xiàn) Goroutine Local Storage 的庫 jtolds/gls ，我們可以通過它在外面封裝一層來實現(xiàn)，并且還需要重新實現(xiàn) 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()
 //對于超時的,統(tǒng)一打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 庫提供的方法封裝實現(xiàn)。

//  Get spanID 用于Goroutine的鏈路追蹤
func GetSpanID() (spanID string) {
 span, ok := mgr.GetValue(spanIDKey)
 if ok {
  spanID = span.(string)
 }
 return
}

日志打印的話，也是對超過 500 毫秒的SQL執(zhí)行進行 Warn 級別日志的打印，方便線上環(huán)境分析問題，而其他的SQL執(zhí)行記錄，因為使用了 Debug 日志級別只會在測試環(huán)境上顯示。

總結
用分布式鏈路追蹤參數(shù)串聯(lián)起整個服務請求的業(yè)務日志，在線上的分布式環(huán)境中是非常有必要的，其實上面只是簡單闡述了一些思路，只有把日志搞的足夠好，上下文信息足夠多才會能高效地定位出線上問題。感覺這部分細節(jié)太多，想用一篇文章闡述明白非常困難。

而且還有一點就是日志錯誤級別的選擇也非常有講究，如果本該用Debug的地方，用了 Info 級別，那線上日志就會出現(xiàn)非常多的干擾項。

細節(jié)的地方怎么實現(xiàn)，就屬于實踐的時候才能把控的了。 希望這篇文章能給你個實現(xiàn)分布式日志追蹤的主旨思路。