分布式链路追踪(Tracing)系统 - Jaeger在Golang中的使用

先从微服务说起

微服务

一个完整的微服务体系至少需要包括:

CI / CD 也就是自动化部署
服务发现
统一的PRC协议
监控
追踪(Tracing)

要配置上面这些东西可谓说超级复杂, 所以我建议读者如果可以直接使用istio

istio

它强大到包含了微服务开发需要考虑的所有东西, 上图中的"Observe"就包括了这篇文章所说的"链路追踪(Tracing)".

但软件行业没有银弹, 强大的工具自然需要强大的人员去管理, 在进阶为大佬之前, 还是得研究一些传统的方案以便成长, 所以便有了这篇文章.

Tracing在微服务中的作用

和传统单体服务不同, 微服务通常部署在一个分布式的系统中, 并且一个请求可能会经过好几个微服务的处理, 这样的环境下错误和性能问题就会更容易发生, 所以观察(Observe)尤为重要,
这就是Tracing的用武之地, 它收集调用过程中的信息并可视化, 让你知道在每一个服务调用过程的耗时等情况, 以便及早发现问题.

Jaeger UI

在上图可以看到api层一共花了4.03s, 然后其中调用其他服务: 'service-1'花了2.12s, 而service-1又调用了'service-2'花费了2.12s, 用这样的图示很容易就能排查到系统存在的问题. 在这里我只展示了时间, 如果需要追踪其他信息(如错误信息)也是可以实现的.

为什么是Jaeger

笔者正在学习Golang, 选用使用Golang并开源的Tracing系统 - Jaeger当然就不再需要理由了

Uber出品也不会太差。

安装

官方文档在此

为了快速上手, 官方提供了"All in One"的docker镜像, 启动Jaeger服务只需要一行代码:

$ docker run -d --name jaeger \
  -e COLLECTOR_ZIPKIN_HTTP_PORT=9411 \
  -p 5775:5775/udp \
  -p 6831:6831/udp \
  -p 6832:6832/udp \
  -p 5778:5778 \
  -p 16686:16686 \
  -p 14268:14268 \
  -p 9411:9411 \
  jaegertracing/all-in-one:1.12

具体端口作用就不再赘述, 官方文档都有.

All in One只应该用于实验环境. 如果是生产环境, 你需要按官方[这样部署].(https://www.jaegertracing.io/docs/1.12/deployment/)
本文在后面会讲到部署并使用Elasticsearch作为存储后端.

现在用于测试的服务端就完成了, 你可以访问http://{host}:16686来访问JaegerUI, 它像这样:

JeagerUi

客户端

部署完服务器就可以编写客户端了, 官方提供了Go/Java/Node.js/Python/C++/C#语言的客户端库, 读者可自行选择, 使用方式可在各自的仓库中查看.

我也只实验了Golang客户端, 先从最简单的场景入手:

在单体应用中实现Tracing.

在编写代码之前还得理解下Jaeger中最基础的几个概念, 也是OpenTracing
的数据模型: Trace / Span

Trace: 调用链, 其中包含了多个Span.
Span: 跨度, 计量的最小单位, 每个跨度都有开始时间与截止时间. Span和Span之间可以存在References(关系): ChildOf 与 FollowsFrom

如下图 (来至开放分布式追踪（OpenTracing）入门与 Jaeger 实现)

单个 Trace 中，span 间的因果关系


        [Span A]  ←←←(the root span)
            |
     +------+------+
     |             |
 [Span B]      [Span C] ←←←(Span C 是 Span A 的孩子节点, ChildOf)
     |             |
 [Span D]      +---+-------+
               |           |
           [Span E]    [Span F] >>> [Span G] >>> [Span H]
                                       ↑
                                       ↑
                                       ↑
                         (Span G 在 Span F 后被调用, FollowsFrom)

接下来是代码时间, 参考项目的Readme和搜索引擎不难写出以下代码

package tests

import (
    "context"
    "github.com/opentracing/opentracing-go"
    "github.com/uber/jaeger-client-go"
    "log"
    "testing"
    "time"

    jaegercfg "github.com/uber/jaeger-client-go/config"
)

func TestJaeger(t *testing.T) {
    cfg := jaegercfg.Configuration{
        Sampler: &jaegercfg.SamplerConfig{
            Type:  jaeger.SamplerTypeConst,
            Param: 1,
        },
        Reporter: &jaegercfg.ReporterConfig{
            LogSpans:           true,
            LocalAgentHostPort: "{host}:6831", // 替换host
        },
    }

    closer, err := cfg.InitGlobalTracer(
        "serviceName",
    )
    if err != nil {
        log.Printf("Could not initialize jaeger tracer: %s", err.Error())
        return
    }

    var ctx = context.TODO()
    span1, ctx := opentracing.StartSpanFromContext(ctx, "span_1")
    time.Sleep(time.Second / 2)

    span11, _ := opentracing.StartSpanFromContext(ctx, "span_1-1")
    time.Sleep(time.Second / 2)
    span11.Finish()

    span1.Finish()

    defer closer.Close()
}

代码唯一需要注意的地方是closer, 这个closer在程序结束时一定记得关闭, 因为在客户端中span信息的发送不是同步发送的, 而是有一个暂存区, 调用closer.Close()就会让暂存区的span发送到agent.

运行之, 我们就可以在UI看到:

点击进入详情就能看到我们刚刚收集到的调用信息

通过Grpc中间件使用

在单体程序中, 父子Span通过context关联, 而context是在内存中的, 显而易见这样的方法在垮应用的场景下是行不通的.

垮应用通讯使用的方式通常是"序列化", 在jaeger-client-go库中也是通过类似的操作去传递信息, 它们叫:Tracer.Inject() 与 Tracer.Extract().

其中inject方法支持将span系列化成几种格式:

Binary: 二进制
TextMap: key=>value
HTTPHeaders: Http头, 其实也是key=>value

正好grpc支持传递metadata也是string的key=>value形式, 所以我们就能通过metadata实现在不同应用间传递Span了.

这段代码在github上有人实现了: https://github.com/grpc-ecosystem/go-grpc-middleware

题外话:上面的库使用到了grpc的Interceptor, 但grpc不支持多个Interceptor, 所以当你又使用到了其他中间件(如grpc_retry)的话就能导致冲突. 同样也可以使用这个库grpc_middleware.ChainUnaryClient解决这个问题.

在grpc服务端的中间件代码如下(已省略错误处理)

import (
    "context"
    "github.com/grpc-ecosystem/go-grpc-middleware/tracing/opentracing"
    "google.golang.org/grpc"
)

jcfg := jaegercfg.Configuration{
        Sampler: &jaegercfg.SamplerConfig{
            Type:  "const",
            Param: 1,
        },
        ServiceName: "serviceName",
    }

report := jaegercfg.ReporterConfig{
        LogSpans:           true,
        LocalAgentHostPort: "locahost:6831",
    }

reporter, _ := report.NewReporter(serviceName, jaeger.NewNullMetrics(), jaeger.NullLogger)
tracer, closer, _ = jcfg.NewTracer(
        jaegercfg.Reporter(reporter),
)

server := grpc.NewServer(grpc.UnaryInterceptor(grpc_opentracing.UnaryServerInterceptor(grpc_opentracing.WithTracer(tracer))))

在grpc客户端的中间件代码如下

conn, err := grpc.Dial(addr, grpc.WithUnaryInterceptor(grpc_opentracing.UnaryClientInterceptor(
    grpc_opentracing.WithTracer(tracer),
)))

现在服务端和客户端之间的调用情况就能被jaeger收集到了.

在业务代码中使用

有时候只监控一个"api"是不够的，还需要监控到程序中的代码片段(如方法)，可以这样封装一个方法


package tracer

type SpanOption func(span opentracing.Span)

func SpanWithError(err error) SpanOption {
    return func(span opentracing.Span) {
        if err != nil {
            ext.Error.Set(span, true)
            span.LogFields(tlog.String("event", "error"), tlog.String("msg", err.Error()))
        }
    }
}

// example:
// SpanWithLog(
//    "event", "soft error",
//    "type", "cache timeout",
//    "waited.millis", 1500)
func SpanWithLog(arg ...interface{}) SpanOption {
    return func(span opentracing.Span) {
        span.LogKV(arg...)
    }
}

func Start(tracer opentracing.Tracer, spanName string, ctx context.Context) (newCtx context.Context, finish func(...SpanOption)) {
    if ctx == nil {
        ctx = context.TODO()
    }
    span, newCtx := opentracing.StartSpanFromContextWithTracer(ctx, tracer, spanName,
        opentracing.Tag{Key: string(ext.Component), Value: "func"},
    )

    finish = func(ops ...SpanOption) {
        for _, o := range ops {
            o(span)
        }
        span.Finish()
    }

    return
}

使用

newCtx, finish := tracer.Start("DoSomeThing", ctx)
err := DoSomeThing(newCtx)
finish(tracer.SpanWithError(err))
if err != nil{
  ...
}

最后能得到一个像这样的结果

可以看到在服务的调用过程中各个span的时间，这个span可以是一个微服务之间的调用也可以是某个方法的调用。

点开某个span也能看到额外的log信息。

通过Gin中间件中使用

在我的项目中使用http服务作为网关提供给前端使用，那么这个http服务层就是root span而不用关心父span了，编写代码就要简单一些。

封装一个gin中间件就能实现

import (
    "context"
    "github.com/gin-gonic/gin"
    "github.com/opentracing/opentracing-go"
    "github.com/opentracing/opentracing-go/ext"
)

jcfg := jaegercfg.Configuration{
        Sampler: &jaegercfg.SamplerConfig{
            Type:  "const",
            Param: 1,
        },
        ServiceName: "serviceName",
    }

report := jaegercfg.ReporterConfig{
        LogSpans:           true,
        LocalAgentHostPort: "locahost:6831",
    }

reporter, _ := report.NewReporter(serviceName, jaeger.NewNullMetrics(), jaeger.NullLogger)
tracer, closer, _ = jcfg.NewTracer(
        jaegercfg.Reporter(reporter),
)

engine.Use(func(ctx *gin.Context) {
        path := ctx.Request.URL.Path

        span := tracer.StartSpan(path,
            ext.SpanKindRPCServer)
        ext.HTTPUrl.Set(span, path)
        ext.HTTPMethod.Set(span, ctx.Request.Method)
        c := opentracing.ContextWithSpan(context.Background(), span)

        ctx.Set("ctx", c)

        ctx.Next()

        ext.HTTPStatusCode.Set(span, uint16(ctx.Writer.Status()))
        span.Finish()
    })

如果需要向下层传递context则这样获取context

func Api(gtx *gin.Context) {
  ctx = gtx.Get("ctx").(context.Context)
}

结语

使用trace会入侵部分代码，特别是追踪一个方法，但这是不可避免的。

甚至需要每个方法都需要添加上ctx, 关于这点有兴趣的朋友可以读一下这篇文章: Golang Context 是好的设计吗？
(原文找不到了, 将就看一下)

但其实并不是整个系统的服务都需要追踪，可只针对于重要或者有性能问题的地方进行追踪。

部署篇

使用Elasticsearch作为存储后端

在一篇文章开放分布式追踪（OpenTracing）入门与 Jaeger 实现中偶然发现阿里云支持为Jaeger提供存储后端, 但怕于阿里云拖更, 所以也就没使用阿里云产品.

笔者对于Elasticsearch更为熟悉, 故选择它了.

es的部署就不说了.

这里是jaeger的docker-compose.yaml

version: '2'
services:
  jaeger-agent:
    image: jaegertracing/jaeger-agent:1.12
    stdin_open: true
    tty: true
    links:
    - jaeger-collector:jaeger-collector
    ports:
    - 6831:6831/udp
    command:
    - --reporter.grpc.host-port=jaeger-collector:14250

  jaeger-collector:
    image: jaegertracing/jaeger-collector:1.12
    environment:
      SPAN_STORAGE_TYPE: elasticsearch
      ES_SERVER_URLS: http://elasticsearch:9200
    stdin_open: true
    external_links:
    - elasticsearch/elasticsearch:elasticsearch
    tty: true

  jaeger-query:
    image: jaegertracing/jaeger-query:1.12
    environment:
      SPAN_STORAGE_TYPE: elasticsearch
      ES_SERVER_URLS: http://elasticsearch:9200
    stdin_open: true
    external_links:
    - elasticsearch/elasticsearch:elasticsearch
    tty: true
    ports:
    - 16686:16686/tcp

其中agent和collect都被设计成无状态的，也就意味着他们可以被放在代理(如Nginx)后面而实现负载均衡。

幸运的是笔者在部署过程中没有遇见任何问题，所以也就没有"疑难杂症"环节了。一般来说遇到的问题都可以去issue搜到。

疑难杂症

<trace-without-root-span>

这个错误原因是: B span 是归属于 A span的, 但Jaeger服务器只收集到了B span, 但没有收集到父级A span, 这时候B span就是一个 without-root-span.

可能原因有下:

忘记调用Finish()
在程序退出时没有调用Closer.Close(), 这会导致缓冲区的spans没有被push到服务器
等待一段时间, 缓冲器Span会经过一段时间(在Golang Client里默认是1S)才会被Push到服务器

发送的Spans个数大于了QueueSize, 多余QueueSize的Spans可能会被丢弃, 这篇文档有提到, 可以通过以下代码配置 QueueSize:

report := jaegercfg.ReporterConfig{
      LogSpans:           false,
      QueueSize:          1000,
      LocalAgentHostPort: agent,
      CollectorEndpoint:  collector,
  }

有时候Jaeger上有数据, 有时候没有

由于客户端和Jaeger-Agent之间是通过UDP协议传输的, 所以如果测试服务器与Jager-Agent服务之间是外网网络环境, 则可能会导致丢包, 通常包越大越容易丢包.

解决办法是将Agent部署到本机, 不过在开发环境为了方便也可以将客户端配置使用Jaeger-Collector, 这时会使用HTTP协议发送Spans.

这在官方文档中有提到:

JAEGER_AGENT_HOST defines hostname for reporting spans over UDP/Thrift. To avoid packet loss, the agent is expected to run on the same machine as the application. This var is useful when there are multiple networking namespaces on the host.

JAEGER_ENDPOINT defines the URL for reporting spans via HTTP/Thrift. This setting allows for a deployment mode where spans are submitted directly to the collector.