August 6, 2020

Opentracing实战

解决微服务架构下,链路追踪,问题定位和可视化分析等问题,链路追踪还是微服务可观测性的重要基石,本文就实战了在Go项目中如何将opentracing落地

背景

在没有链路追踪系统的情况下,如果只要少数几个服务,或许还可以通过日志来排查定位问题。但是如果服务一旦超过10个,那么再想通过日志来定位分析问题将无比繁琐。 因为,你先要从大量的日志中删筛选出某次请求的日志数据,才能进行后续的定位分析。 倘若日志系统也不够完善,日志对于调试毫无帮助,那又得退回到最原始的方式,通过代码断点和增加日志,等待问题复现,或者通过肉眼检查代码。 不是说这种方式不行,而是大部分的程序员的业务需求比较紧张,这样的排查手段效率和收益远远达不到要求(如果你有时间,当我没说 🐶)。

在实际场景中,我也遇到了这样的问题:

  1. 日志系统里包含了过少的信息,对于调试几乎没有帮助 (几乎只有错误日志,缺少输出上下文的日志)。
  2. 服务调用复杂,一个请求失败,只能透过错误码和错误信息进行判断是否存在调用失败的情况。
  3. 调用链路复杂的情况下,想要对某个请求进行优化,无从下手。

这里只列举了跟trace相关的一些原始场景,当然从上面的描述中还能发现日志系统不够完善,对调试不友好,不过这里首要解决的问题是链路追踪问题

如果对路链路追踪没有概念,还望自行查阅资料,这里不会过多介绍~

Opentracing

注意:Opentracing 是一套标准接口,而不是具体实现。

这里就实战opentracing + jaeger 的链路追踪方案。其中 opentracing 是一套标准接口,而jaeger是包含了 opentracing 的实现的一套工具。 Trace链路简单示例如下:

Trace

描述在分布式系统中的一次"事务"。

Span

表示工作流的一部分的命名和定时操作。可以接受标签(Tag Key:Value),以及附加到特定span实例的标注(Annotation),如时间戳和结构化日志。

SpanContext

追踪伴随分布式事务的信息,包括它通过网络或通过消息总线将服务传递给服务的时间。span上下文包含TraceId、SpanId和追踪系统需要传播到下游服务的其他数据。

实战

这里我准备的是 Go 项目,服务之间通过gRPC通信。链路如下:

                                +-- process internal trace2
                                |
                     +---> process internal trace1
                     |
                     |                 +---> server-b trace(gRPC)
entry(HTTP) ---> server-a trace--gRPC--|
                                       +---> server-c trace(gRPC)
                                                   |
                                                   +----> process internal trace3

从上图中可以明确,我们的目标是:实践跨服务调用服务内部调用的链路追踪,配合jaeger我们还可以将链路信息可视化。

我有了服务,怎么实施落地?

为了回答这个问题,我把这个问题结合opentracing的概念再分解一下:

  1. ParentSpan 从哪儿来?
  2. ChildSpan由ParentSpan创建,那么什么时候创建?
  3. 链路Tracer从哪儿来?
  4. Trace信息怎么传递?
  5. 链路信息如何搜集?
Parent-Span 从哪儿来?链路从哪里开始。

在上述的实践目标中,我们只有一个入口服务,那么很明显每一次的"事务"都是在这个入口(http entry)开启的。我写了如下的中间件(基于gin)。

// 这个定义是因为opentracing没有定义获取traceId 和spanId的方法,而我又实践了 zipkin 和 jaeger
type getTraceID func(spCtx opentracing.SpanContext) string

// get trace info from header, if not then create an new one
func Opentracing(getTraceIdFromSpanContext getTraceID) gin.HandlerFunc {
    return func(c *gin.Context) {
        // prepare work ...
        
    	// 这里首先尝试从客户端请求中获取到trace链路信息,如果获取到则创建child span.
        carrier := opentracing.HTTPHeadersCarrier(c.Request.Header)
        clientSpCtx, err := tracer.Extract(opentracing.HTTPHeaders, carrier)
        if err != nil {
            log.Printf("could not extract trace data from http header, err=%v\n", err)
        }

        // derive a span or create an root span
        sp = tracer.StartSpan(
            c.Request.RequestURI,
            opentracing.ChildOf(clientSpCtx),
        )
        defer sp.Finish()
        
        // do some work
        // ...
        
        // 将含有span的 context.Context 设置到 gin.Context 用于传递span
        ctx = opentracing.ContextWithSpan(c.Request.Context(), sp)
        c.Set(_traceContextKey, ctx)
        traceId := getTraceIdFromSpanContext(sp.Context())
        c.Header("X-Trace-Id", traceId)
        
        // continue process request
        c.Next()
        
        // do some work 
        // ...
    }
}
Child-Span什么时候创建?

其实在上述的中间件里已经有了体现(跨服务调用时)。这里主要有两种场景:跨服务调用服务内部调,这两种的区别在于是否是同一个进程。 针对跨服务调用,我们使用了gRPC来通信,那么创建的时机就在于gRPC客户端发起调用时,需要创建一个childSpan并传递给服务端,服务端需要解析到该span并在当次请求中使用。 而对于服务内部的调用,相较而言会更简单一点,直接使用该span创建childSpan就好了。

这里需要注意的是,一般来说在Go开发过程中推荐使用Context作为函数调用的第一个参数,opentracing也考虑了这一点,如下: 官方提供了对应的方法,来帮助使用者把span和context.Context一起使用。

// ContextWithSpan returns a new `context.Context` that holds a reference to
// the span. If span is nil, a new context without an active span is returned.
func ContextWithSpan(ctx context.Context, span Span) context.Context {
	if span != nil {
		if tracerWithHook, ok := span.Tracer().(TracerContextWithSpanExtension); ok {
			ctx = tracerWithHook.ContextWithSpanHook(ctx, span)
		}
	}
	return context.WithValue(ctx, activeSpanKey, span)
}

// SpanFromContext returns the `Span` previously associated with `ctx`, or
// `nil` if no such `Span` could be found.
//
// NOTE: context.Context != SpanContext: the former is Go's intra-process
// context propagation mechanism, and the latter houses OpenTracing's per-Span
// identity and baggage information.
func SpanFromContext(ctx context.Context) Span {
	val := ctx.Value(activeSpanKey)
	if sp, ok := val.(Span); ok {
		return sp
	}
	return nil
}

在中间件那里,我们已经把 context.Context 设置到了 gin.Context 中去了,因此在后续的使用中,我们需要把它从 gin.Context 取出并传递。

// traceHdl is a trace handler from HTTP request
func traceHdl(c *gin.Context) {
	// get root Context from request
	// TODO: try to use c.Request.WithContext() to set context
	ctx, ok := c.Get(x.GetTraceContextKey())
	if !ok {
		panic("impossible")
	}
	
    // ctx在服务内部传递,ctx含有span信息
	if err := clientCall(ctx.(context.Context)); err != nil {
		c.JSON(http.StatusInternalServerError, gin.H{"message": err.Error()})
		return
	}

	// response to client
	c.JSON(http.StatusOK, gin.H{"message": "traceHdl done"})
}


func clientCall(ctx context.Context) error {
    // 注意:这里使用了gRPC来做跨服务的调用,对于ctx的处理,是通过interceptor实现的。
	// 这部分代码会在后面贴上,但是逻辑也跟类似,只是多了需要适配gRPC数据传递的规则。
	_, err := serverAConn.PingA(ctx, &pb.PingAReq{
		Now:  time.Now().Unix(),
		From: "client",
	})

	if err != nil {
		return err
	}

	// 这里演示进程内链路
	return processInternalTrace1(ctx)
}

// internal process trace example 1
func processInternalTrace1(ctx context.Context) error {
	ctx2, sp := x.StartSpanFromContext(ctx)
	defer sp.Finish()

	println("processInternalTrace1 called")
	// do some ops
	time.Sleep(10 * time.Millisecond)

	return processInternalTrace2(ctx2)
}

gRPC interceptor 实现如下:服务端工作内容相似,只是从inject操作变成了extract。

// client interceptor
func OpenTracingClientInterceptor(tracer opentracing.Tracer, optFuncs ...Option) grpc.UnaryClientInterceptor {
	otgrpcOpts := newOptions()
	otgrpcOpts.apply(optFuncs...)
	return func(
        ctx context.Context,m
        ethod string, 
        req, resp interface{}, 
        cc *grpc.ClientConn, 
        invoker grpc.UnaryInvoker, 
        opts ...grpc.CallOption,
    ) error {
        var err error
        var parentCtx opentracing.SpanContext
        if parent := opentracing.SpanFromContext(ctx); parent != nil {
            parentCtx = parent.Context()
        }
        // ...
        
        clientSpan := tracer.StartSpan(
            method,
            opentracing.ChildOf(parentCtx),
            ext.SpanKindRPCClient,
            gRPCComponentTag,
        )
        defer clientSpan.Finish()
        
        // 注入
        ctx = injectSpanContext(ctx, tracer, clientSpan)
        // ...
        
        // 调用
        err = invoker(ctx, method, req, resp, cc, opts...)
        // ...		
        
        return err 
    }
}

func injectSpanContext(ctx context.Context, tracer opentracing.Tracer, clientSpan opentracing.Span) context.Context {
	md, ok := metadata.FromOutgoingContext(ctx)
	if !ok {
		md = metadata.New(nil)
	} else {
		md = md.Copy()
	}
	mdWriter := metadataReaderWriter{md}
	err := tracer.Inject(clientSpan.Context(), opentracing.HTTPHeaders, mdWriter)
	// We have no better place to record an error than the Span itself :-/
	if err != nil {
		clientSpan.LogFields(log.String("event", "Tracer.Inject() failed"), log.Error(err))
	}
	return metadata.NewOutgoingContext(ctx, md)
}

至此我们就介绍完了,服务间(gRPC)调用和服务内(context)调用的childSpan的创建和传递。

链路Tracer从哪儿来?

先说Tracer有什么用,Tracer是用来管理Span的统筹者,负责创建span和传播span。

// Tracer负责创建span和传播span
type Tracer interface {

	// Create, start, and return a new Span with the given `operationName` and
	// incorporate the given StartSpanOption `opts`. (Note that `opts` borrows
	// from the "functional options" pattern, per
	// http://dave.cheney.net/2014/10/17/functional-options-for-friendly-apis)
	//
	// A Span with no SpanReference options (e.g., opentracing.ChildOf() or
	// opentracing.FollowsFrom()) becomes the root of its own trace.
	//
	// Examples:
	//
	//     var tracer opentracing.Tracer = ...
	//
	//     // The root-span case:
	//     sp := tracer.StartSpan("GetFeed")
	//
	//     // The vanilla child span case:
	//     sp := tracer.StartSpan(
	//         "GetFeed",
	//         opentracing.ChildOf(parentSpan.Context()))
	//
	//     // All the bells and whistles:
	//     sp := tracer.StartSpan(
	//         "GetFeed",
	//         opentracing.ChildOf(parentSpan.Context()),
	//         opentracing.Tag{"user_agent", loggedReq.UserAgent},
	//         opentracing.StartTime(loggedReq.Timestamp),
	//     )
	//
	StartSpan(operationName string, opts ...StartSpanOption) Span

	// Inject() takes the `sm` SpanContext instance and injects it for
	// propagation within `carrier`. The actual type of `carrier` depends on
	// the value of `format`.
	//
	// OpenTracing defines a common set of `format` values (see BuiltinFormat),
	// and each has an expected carrier type.
	//
	// Other packages may declare their own `format` values, much like the keys
	// used by `context.Context` (see https://godoc.org/context#WithValue).
	//
	// Example usage (sans error handling):
	//
	//     carrier := opentracing.HTTPHeadersCarrier(httpReq.Header)
	//     err := tracer.Inject(
	//         span.Context(),
	//         opentracing.HTTPHeaders,
	//         carrier)
	//
	// NOTE: All opentracing.Tracer implementations MUST support all
	// BuiltinFormats.
	//
	// Implementations may return opentracing.ErrUnsupportedFormat if `format`
	// is not supported by (or not known by) the implementation.
	//
	// Implementations may return opentracing.ErrInvalidCarrier or any other
	// implementation-specific error if the format is supported but injection
	// fails anyway.
	//
	// See Tracer.Extract().
	Inject(sm SpanContext, format interface{}, carrier interface{}) error

	// Extract() returns a SpanContext instance given `format` and `carrier`.
	//
	// OpenTracing defines a common set of `format` values (see BuiltinFormat),
	// and each has an expected carrier type.
	//
	// Other packages may declare their own `format` values, much like the keys
	// used by `context.Context` (see
	// https://godoc.org/golang.org/x/net/context#WithValue).
	//
	// Example usage (with StartSpan):
	//
	//
	//     carrier := opentracing.HTTPHeadersCarrier(httpReq.Header)
	//     clientContext, err := tracer.Extract(opentracing.HTTPHeaders, carrier)
	//
	//     // ... assuming the ultimate goal here is to resume the trace with a
	//     // server-side Span:
	//     var serverSpan opentracing.Span
	//     if err == nil {
	//         span = tracer.StartSpan(
	//             rpcMethodName, ext.RPCServerOption(clientContext))
	//     } else {
	//         span = tracer.StartSpan(rpcMethodName)
	//     }
	//
	//
	// NOTE: All opentracing.Tracer implementations MUST support all
	// BuiltinFormats.
	//
	// Return values:
	//  - A successful Extract returns a SpanContext instance and a nil error
	//  - If there was simply no SpanContext to extract in `carrier`, Extract()
	//    returns (nil, opentracing.ErrSpanContextNotFound)
	//  - If `format` is unsupported or unrecognized, Extract() returns (nil,
	//    opentracing.ErrUnsupportedFormat)
	//  - If there are more fundamental problems with the `carrier` object,
	//    Extract() may return opentracing.ErrInvalidCarrier,
	//    opentracing.ErrSpanContextCorrupted, or implementation-specific
	//    errors.
	//
	// See Tracer.Inject().
	Extract(format interface{}, carrier interface{}) (SpanContext, error)
}

之前已经提到了了opentracing是一套接口,那么具体的实现是在其他的工具中完成的,如jaeger。创建的时候就需要jaeger的支持了,如下:

// 使用jaeger来创建一个tracer,并注入到opentracing全局中去
func BootTracerWrapper(localServiceName string, hostPort string) error {
	tracer, err := xjaeger.BootJaegerTracer(localServiceName, hostPort)
	if err != nil {
		return errors.Wrap(err, "BootTracerWrapper.BootZipkinTracer")
	}

    // 注入到全局后,就可以通过 opentracing.GlobalTracer() 来使用 tracer了 
	opentracing.SetGlobalTracer(tracer)

	return nil
}

func BootJaegerTracer(localServiceName, hostPort string) (opentracing.Tracer, error) {
	cfg := &config.Configuration{
		Sampler: &config.SamplerConfig{
			Type:  jaeger.SamplerTypeConst,
			Param: 1,
		},
		ServiceName: localServiceName, // 服务名
		Reporter: &config.ReporterConfig{
			LogSpans:          true,
			CollectorEndpoint: _jaegerRecorderEndpoint,
		}, // 链路搜集配置
	}

	tracer, _, err := cfg.NewTracer(
		config.Logger(jaegerlog.StdLogger),
		config.ZipkinSharedRPCSpan(true),
	)
	if err != nil {
		return nil, errors.Wrap(err, "BootJaegerTracer")
	}

	return tracer, nil
}
Trace信息怎么传递?

Child-Span什么时候创建? 中提到了 Inject, Extract 方法,这两个方法就是用来辅助Trace信息传递的方法, 具体的实现也是在jaeger中实现的,有兴趣的可以自行查阅代码。

链路信息如何搜集?

#链路Tracer从哪儿来 已经提到了jaeger在创建tracer时可以指定搜集器的配置, 因此上报动作会在jaeger中完成,但是要注意的是,显式调用 sp.Finish() 才会触发上报动作。

总结

最终实战结果截图如下: 图中包含了调用链路层级关系,每个环节的耗时情况,请求的入参和结果数据(异常信息,如有)等。同时还支持自定义(Tag 和 Annotation 功能), 如果还想要更多的信息,那么推荐使用这两个功能组合来满足需求。

再多的案例和文档,都没有自己上手实践的效果好,建议实际运行并查阅opentracing源码。所有的代码均可在 https://github.com/yeqown/opentracing-practice 中找到。

水平有限,如有错误,欢迎勘误指正🙏。

参考文献