本文转载自微信公众号《网管唠叨bi唠叨》，作者KevinYan11。转载本文请联系网管谢bi公众号。现在微服务架构盛行，很多以前的单体应用服务被拆解成多个分布式微服务，以解决应用系统增长后开发周期长、扩展难、故障隔离等挑战。然而，技术领域有一句谚语叫——没有银弹。这句话的意思和现实生活中的任何事情都有好处和坏处是一样的。旧问题的解决方案必然会引入新问题。通常，在单体应用中，可以使用本地数据库的ACID事务来保证数据的一致性。但是微服务拆分之后，就不那么简单了。同样，拆分成服务后，一个业务逻辑的完成一般需要多个服务的配合。每个服务都会有自己的业务日志。如何将各个服务的业务日志串联起来，也会变得困难。今天来聊聊微服务的日志拼接方案。上一篇分布式链路跟踪中的traceid和spanid代表什么？这里给大家介绍一下TraceId和SpanId的概念。trace是请求分布式系统中的整个链路视图，span代表整个链路中不同服务的内部视图。跨度的组合是整个轨迹的视图。在微服务的日志系列中，我们也可以使用这两个概念，通过trace将一个业务逻辑的所有业务日志进行串接，通过span将单个服务中的业务日志进行串接。当单个微服务的日志串联起来时，另一个挑战是如何将数据库执行过程的一些日志注入到这些traceids和spanids中，打入业务日志中。接下来，我们将通过在HTTP服务之间传递日志跟踪参数，在HTTP和RPC服务之间传递跟踪参数，以及将跟踪参数注入ORM日志来简单描述连接微服务业务日志的思路。提前声明，本文给出的方案大多基于Go技术栈。一些解决方案在其他语言的技术栈中的实现与这里列出的略有不同，尤其是在Java中一些开源库上更容易实现的东西，在Go中是没有的。简单的。其实如果使用APM，有比较统一的解决方案，比如接入Skywalking，但是还是有额外的学习成本，需要引入外部系统组件。HTTP服务间日志跟踪参数的传递HTTP服务间跟踪参数的传递主要由全局路由中间件完成。我们可以在请求头中指定TraceId和SpanId。当然，如果是请求到达的第一个服务，会生成TraceId和SpanId，添加到Header中向下传递。typeMiddlewarefunc(http.HandlerFunc)http.HandlerFuncfuncwithTrace()Middleware{//创建中间件xx-tranceid")parentSpanID:=r.Header.Get("xx-spanid")spanID:=genSpanID(r.RemoteAddr)iftraceID==""{//traceID为空，证明是初始调用，letrootspanid==traceidtraceId=spanID}//服务内部处理中通过Context传递trace参数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)//调用下一个中间件或最终处理程序handlerf(w,r)}}}上面主要是在中间件程序中获取Header中保存的跟踪参数，将参数保存在请求Context中，并在服务内部传递。上述程序中有几点需要说明：genSpanID是一种根据远程客户端IP生成唯一spanId的方法，生成方法只需要保证hash字符串唯一即可。如果服务是请求的开始，那么在生成spanId的时候，我们也将其设置为traceId，这样就可以通过spanId==traceId来判断当前的Span是请求的开始，也就是根span。接下来，当我们向下游服务发起请求时，需要将存储在Context中的跟踪参数放入Header中，然后传递给下一个HTTP服务。funcHttpGet(ctxcontext.Contexturlstring,datastring,timeoutint64)(codeint,contentstring,errerror){req,_:=http.NewRequest("GET",url,strings.NewReader(data))deferreq.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服务之间传递跟踪参数我们上面说的上下游服务都是HTTP服务跟踪参数，那么如果HTTP服务的下游是RPC服务呢？其实就像发送HTTP请求一样，可以配置HTTP客户端携带Header和Context，RPC客户端也支持类似的功能。以gRPC服务为例，当客户端调用RPC方法时，在可以携带的元数据中设置这些跟踪参数。traceID:=ctx.Value("trace-id").(string)traceID:=ctx.Value("trace-id").(string)md:=metadata.Pairs("xx-traceid",traceID,"xx-spanid",spanID)//创建一个新的contextctx:=metadata.NewOutgoingContext(context.Background(),md)//单向UnaryRPResponse,err:=client.SomeRPCMethod(ctx,someRequest)RPCservicewithmetadataIn端处理方法，可以通过元数据检索存储在元数据中的跟踪参数。func(sserver)SomeRPCMethod(ctxcontext.Context,req*xx.someRequest)(reply*xx.SomeReply,errerror){remote,_:=peer.FromContext(ctx)remoteAddr:=remote.Addr.String()//生成本次请求的spanIdspanID:=utils.GenerateSpanID(remoteAddr)traceID,pSpanID:="",""md,_:=metadata.FromIncomingContext(ctx)ifarr:=md["xx-tranceid"];len(arr)>0{traceID=arr[0]}ifarr:=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生态中的中间件客户端拦截器funcUnaryClientInterceptor(ctxcontext.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...)returnerr}//连接服务器conn,err:=grpc.Dial(*address,grpc.WithInsecure(),grpc.WithUnaryInterceptor(UnaryClientInterceptor))服务结束拦截器funcUnaryServerInterceptor(ctxcontext.Context,reqinterface{},info*grpc.UnaryServerInfo,handlergrpc.UnaryHandler)(respinterface{},errerror){remote,_:=peer.FromContext(ctx)remoteAddr:=remote.Addr.String()spanID:=utils.GenerateSpanID(remoteAddr)//settracingspanidtraceID,pSpanID:="",""md,_:=metadata.FromIncomingContext(ctx)ifarr:=md["xx-traceid"];len(arr)>0{traceID=arr[0]}ifarr:=md["xx-spanid"];len(arr)>0{pSpanID=arr[0]}//把这几个ID放到ctx中，另外两个一次省略ctx:=Context.WithValue(ctx,"traceId",traceId)resp,err=handler(ctx,req)return}注入trace参数到ORM日志中其实如果用GORM注入这个参数是最难的，如果你是Java程序员，你可能习惯在阿里巴巴的Druid数据库连接池中加入traceId之类的参数，但是Go的GORM库确实做不到，也许新版本可以，我还是用老的。版本，其他的GoORM库没有接触过，知道的同学可以给我们留言科普一下GORM不能在日志中添加tracking参数的原因是GORM的logger没有实现SetContext方法，所以除非你修改源码调用db.slog，否则什么也做不了。但也不能说是死了。我介绍了一个库jtolds/gls，它使用函数调用栈来实现GoroutineLocalStorage。我们可以用它在外面封装一层来实现，同时我们也需要重新实现GORMLogger方法的Printlog。感受一下，GLS库的使用确实有点奇怪，不过可以通过。funcSetGls(traceID,pSpanID,spanIDstring,cbfunc()){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(llogger)Print(values...interface{}){iflen(values)>1{//...l.sqlLog(sql,args,duration,path.Base(source))}else{err:=values[2]log.Error("source",source,"err",err)}}}func(llogger)sqlLog(sqlstring,args[]interface{},durtime.Duration,sourcestring){argsArr:=make([]string,len(args))fork,v:=rangeargs{argsArr[k]=fmt.Sprintf("%v",v)}argsStr:=strings.Join(argsArr,",")spanId:=gls.GetSpanId()traceId:=gls.GetTraceId()//超时统一发出warnlogifdur>(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库提供的方法包实现。//GetspanID用于Goroutine链接跟踪funcGetSpanID()(spanIDstring){span,ok:=mgr.GetValue(spanIDKey)ifok{spanID=span.(string)}return}如果打印日志，也是为了更多小于500毫秒的SQL执行打印Warn级别的日志，方便线上环境分析问题，其他SQL执行记录，因为使用的是Debug日志级别，只会在测试环境中显示。综上所述，在在线分布式环境中，使用分布式链路跟踪参数将整个服务请求的业务日志串联起来是非常有必要的。其实以上只是对一些思路的简单说明。只有日志足够好，上下文信息足够多，才能高效定位线上问题。感觉这部分细节太多了，很难用一篇文章来说明。还有一点，日志错误级别的选择也很有讲究。如果应该用Debug级别，就用Info级别，在线日志中会有很多干扰项。如何实现细节只能在实践中控制。希望这篇文章能让大家对分布式日志跟踪的实现有一个大概的了解。
