trace信息采集失败问题分析

随着大量云原生技术的应用，IT系统日益复杂，开发人员经常会遇到类似的问题场景：

在业务上遇到问题时，如何才能做到主动感知、预测故障、迅速定位呢？传统的监控方式已经跟不上现有需求了，为此可观测性应运而生。而metrics（指标）、tracing（调用链）、logging（日志）是可观测性的三大支柱，其主要特点为：

基于metrics的告警可以发现异常，通过tracing可以定位到对应模块，根据模块具体的logging可以定位到异常根源，后续可以根据问题调整metrics告警阈值以便提前发现/预防此类问题。

 在tcf框架中，底层是基于goframe做业务服务的，同时在上层对redis，db，kafka等进行了相关封装，增加了metrics、tracing、logging的实现，同时采用opentelemetry标准协议进行数据采集。

在半月前trace和log功能已经上线，同时也接入到了阿里云sls服务中，只有metrics功能没有开发，当时在sls中查看trace和log功能都是正常的。上周在处理metrics相关事项，SRE在集群内部署了prometheus、grafana，同时业务在集群内部署了redis、kafka等服务用来对开发的指标功能进行测试，启用相关的服务调用framework中的方法去生成相关指标，prometheus来拉取对应指标，grafana以prometheus为数据源，通过在grafana配置了各个组件的面板，并导出了配置面板的json文件也都正常可用。

测试过程中，包含三个服务

关系图如下：

开发metrics信息并配置好grafana面板后，查看sls服务的trace信息时，发现只有tcf-app-backend-pro服务的trace信息是正常的，而另外两个服务的trace信息明显有问题，tcf-server-demo和tcf-app-backend-test服务的trace值都没有上报数据。

查看tcf-app-backend-test服务和tcf-server-demo服务的日志发现，日志在上报trace时一直在打印warning日志：

日志排查

从以上日志来看，通过关键字“trace.otlpExporter”先找到打印warning日志的地方，可以查找到是framework的ExportSpans方法打印出来的，但是由于是warning日志，并不清楚调用栈是怎样的。

只能再次查找关键日志，如：“grpc: error while marshaling”，比较幸运的是这次找到只有一处地方有这个日志，那就是在google.golang.org/grpc包下的encode方法中。从方法的调用来看，是执行c.Marshal(msg)的时候报错了。但是问题点就来了：这个msg是什么？为什么会encode失败？

加日志查问题

鉴于上面排查的情况，下一步就需要知道为何encode msg失败了。由于otel-collector、prometheus服务都是部署在集群内部的，且外网访问不了，想尝试debug来操作基本上很难，只能增加相关日志来进行排查了。刚好项目中二进制是通过go vendor模式编译的，为此，可以手动在上面的代码中增加日志打印，首先想到的是把msg和error信息打印出来。修改上述encode方法的代码，增加两行日志：

func encode(c baseCodec, msg interface{}) ([]byte, error) {    if msg == nil { // NOTE: typed nils will not be caught by this check       return nil, nil    }    b, err := c.Marshal(msg)    if err != nil {       fmt.Printf("=========msg:%+v |err:%+v\n",msg,err)       return nil, status.Errorf(codes.Internal, "grpc: error while marshaling: %v", err.Error())    }    fmt.Printf("=========normal msg:%+v\n",msg)    if uint(len(b)) > math.MaxUint32 {       return nil, status.Errorf(codes.ResourceExhausted, "grpc: message too large (%d bytes)", len(b))    }    return b, nil}

代码commit，重新部署后，通过 kubectl logs -f tcfapp-backend-test-xxxxxx -n namespace 查看日志。确实是打印了相关的错误日志，错误信息也还是“invalid UTF8”，但是这个msg信息实际是太长了，至少有几千行，直接看完全看不出有什么问题，不过在msg信息中发现有trace_id，span_id中有些值看起来像是十六进制的数据，还有msg信息中既有可读字符串类型，同时还存在一些十六进制的数据，看起来有点奇怪的样子。初步怀疑是否有什么地方把某些数据做了格式转换，或者数据经过多次转换后导致最后encode的地方识别不了了。

再次根据日志分析

到这里貌似就卡住了，几千行的日志也只能硬着头皮看下去了，不过还是要抓重点，在resource_span中，看前面一部分的日志都是正常的字符串类型，到最后这里变成了十六进制的一些数据，仔细查看这个特殊数据，发现其是span中的attribute信息，对应的key为“http.response.body”，而其value为一串看不懂的十六进制值。

“http.response.body”是个啥

老办法，在代码中全局搜索下关键词“http.response.body”，发现其是来自于goframe自带的trace处理中的，一个在client端，一个在server端。同时根据上图可以看到其对应的name是“/metrics”，User-Agent是“Prometheus”，对于测试来说，确实是暴露了/metrics接口来获取对应的指标信息，那就是说有可能是prometheus是通过/metrics来获取tcf-app-backend-test和tcf-server-demo服务的指标信息，所以这块应该对应的是goframe服务端的span处理。

源码分析一

那就先来看下goframe（当前使用的是v2.2.2版本）中服务端的trace处理源码（部分代码已省略），可参考 server trace middleware：

const (    ...    tracingEventHttpResponseBody                = "http.response.body"    tracingMiddlewareHandled        gctx.StrKey = `MiddlewareServerTracingHandled`)// internalMiddlewareServerTracing is a serer middleware that enables tracing feature using standards of OpenTelemetry.func internalMiddlewareServerTracing(r *Request) {    ...    // Continue executing.    r.Middleware.Next()    // Error logging.    if err := r.GetError(); err != nil {        span.SetStatus(codes.Error, fmt.Sprintf(`%+v`, err))    }    // Response content logging.    var resBodyContent = gstr.StrLimit(r.Response.BufferString(), gtrace.MaxContentLogSize(), "...")    span.AddEvent(tracingEventHttpResponse, trace.WithAttributes(        attribute.String(tracingEventHttpResponseHeaders, gconv.String(httputil.HeaderToMap(r.Response.Header()))),        attribute.String(tracingEventHttpResponseBody, resBodyContent),    ))}

可以看到，对应的attribute的信息，key为tracingEventHttpResponseBody，value为resBodyContent，也即从response中读取的到的响应值。

修改测试

既然resBodyContent数据有问题，那把这个值改为固定值呢，是否trace数据就可以正常上报到sls呢？

修改vendor目录下goframe中上面的代码，把resBodyContent改为固定值“guding  server zhi”，重启部署服务后，查看sls trace信息，发现trace信息确实能够正常上报了。

本地复现

本地启动prometheus服务，利用framework中的example下的testHttp()方法进行测试，启用trace和metrics，在goframe的ghttp_middleware_tracing.go中打上相应的断点，由于本地并没有trace provider，这里需要把ghttp_middleware_tracing.go中的这几行代码注释掉，不然走不到下面的设置属性的方法：

服务启动后，本地浏览器中请求： http://127.0.0.1:8200/metrics 。对应的resBodyContent确实是乱码。

对比分析

那是否处理其他请求的时候resBodyContent的值也是类似的乱码呢？很简单，做个对比进行验证即可。在此直接启动tcf-web的服务，然后通过postman任意调用一个接口，如调用公告列表的接口，在断点处发现响应值是正常的字符串信息。

源码分析二

通过上面的对比，可以得出的结论就是/metrics接口返回的不是正常的字符串数据，那会是啥数据呢，只能查看源码进行分析，可以在本地进行debug，发现在github.com/prometheus/client_golang开源组件中的prometheus/promhttp/http.go中有对响应的相关处理（详细代码可参考：prometheus client-go 代码），相关注释标记在下面的代码中了

func HandlerForTransactional(reg prometheus.TransactionalGatherer, opts HandlerOpts) http.Handler {    ...       var contentType expfmt.Format       if opts.EnableOpenMetrics {          contentType = expfmt.NegotiateIncludingOpenMetrics(req.Header)       } else {          contentType = expfmt.Negotiate(req.Header)       }       header := rsp.Header()       header.Set(contentTypeHeader, string(contentType)) // 简单理解就是拿到req的header，然后写入到rsp的header中       w := io.Writer(rsp)       if !opts.DisableCompression && gzipAccepted(req.Header) { // 如果未禁用压缩，同时req的header中存在gzip的话，下面代码会把rsp的信息进行gzip压缩          header.Set(contentEncodingHeader, "gzip")          gz := gzipPool.Get().(*gzip.Writer)          defer gzipPool.Put(gz)          gz.Reset(w)          defer gz.Close()          w = gz       }       enc := expfmt.NewEncoder(w, contentType)      ...    return http.TimeoutHandler(h, opts.Timeout, fmt.Sprintf(       "Exceeded configured timeout of %v.\n",       opts.Timeout,    ))}

主要关注代码这里的第13行，如果配置项中未禁用压缩，同时req的header中存在gzip的话，会把rsp的信息进行gzip压缩，然后发送出去。所以之前看到的乱码信息就是gzip压缩后的信息了。

再回过头看下之前日志中的header信息，发现对应的content-encoding确实包含gzip。

排查出了原因，修改就很简单了，方案有两种：

方案一：提相关issue到goframe官方，在处理trace时需要支持rsp为gzip之后的数据，需要根据header中是否有gzip来对数据进行处理；

方案二：在配置/metrics的代码中，把DisableCompression设置为true即可。即

s.BindHandler(config.Uri, func(r *ghttp.Request) {    promhttp.InstrumentMetricHandler(       config.Registerer,       promhttp.HandlerFor(config.Gatherer,          promhttp.HandlerOpts{DisableCompression: true})).ServeHTTP(r.Response.Writer, r.Request)})

方案一需要提issue和MR相关信息，还不一定能够合入到goframe主干中，耗时长且不确定。在这里可以采用方案二，方案一到时候可以给goframe提交一个pr看下。重新部署之后sls trace信息正常。

到此该问题真的结束了吗？为什么gzip压缩后的数据就不能够encode成功呢。为此引用framework框架写个demo进行测试，主要包含grpc server和grpc client。其中server端把响应的数据做gzip压缩后再发送给客户端，客户端是正常发送代码。整体代码如下：

pb文件：

syntax = "proto3";//https://grpc.io/docs/languages/go/quickstart/#prerequisites//protoc  --go_out=. --go-grpc_out=. --go-gvalid_out=. proto/greeter.protopackage example;option go_package = "/proto";service Greeter {    // Sends a greeting    rpc SayHello (HelloRequest) returns (HelloReply) {    }}// The request message containing the user's name.message HelloRequest {    // @gvalid:"required#名称不能为空"    string name = 1;}// The response message containing the greetingsmessage HelloReply {    string message = 1;}

server端：

package mainimport (    "bytes"    "compress/gzip"    "context"    "fmt"    "github.com/gogf/gf/v2/os/gctx"    pb "tcf.37ops.com/tcf/framework/example/grpctest/proto"    "tcf.37ops.com/tcf/framework/gt")type greeterServer struct {    pb.UnimplementedGreeterServer}// GZIPEn gzip加密func GZIPEn(str string) []byte {    var b bytes.Buffer    gz := gzip.NewWriter(&b)    if _, err := gz.Write([]byte(str)); err != nil {       panic(err)    }    if err := gz.Flush(); err != nil {       panic(err)    }    if err := gz.Close(); err != nil {       panic(err)    }    return b.Bytes()}func (h *greeterServer) SayHello(ctx context.Context, r *pb.HelloRequest) (*pb.HelloReply, error) {    v := fmt.Sprintf("hello, " + r.GetName())    vv := GZIPEn(v)    return &pb.HelloReply{Message: string(vv)}, nil}func main() {    ctx := gctx.New()    gt.GrpcServer(ctx).Register(&pb.Greeter_ServiceDesc, &greeterServer{})    gt.GrpcServer(ctx).Run()}

client端：

package mainimport (    "context"    "time"    "github.com/gogf/gf/v2/os/gctx"    "google.golang.org/grpc"    pb "tcf.37ops.com/tcf/framework/example/grpctest/proto"    "tcf.37ops.com/tcf/framework/gt")type greeterClient struct {    client pb.GreeterClient}func NewGreeterClient(c grpc.ClientConnInterface) *greeterClient {    return &greeterClient{client: pb.NewGreeterClient(c)}}func (cli *greeterClient) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {    r, err := cli.client.SayHello(ctx, in)    if err != nil {       return nil, err    }    return r, nil}func main() {    ctx := gctx.New()    c := gt.GrpcClient(ctx, "example")    in := pb.HelloRequest{       Name: "test",    }    for {       hello, err := NewGreeterClient(c).SayHello(ctx, &in)       if err != nil {          gt.Log().Errorf(ctx, "client say hello fail, err: %+v", err)          return       }       gt.Log().Printf(ctx, "%v", hello)       time.Sleep(1 * time.Second)    }}

启动服务端，然后再启动客户端，发现问题确实是复现了：

再次debug可以看到相应的堆栈信息：

后续还做了一个验证，把goframe server trace中间件中的response做gzip解压缩，输出对应的信息，发现数据确实就是/metrics接口在gzip之前的信息。

在本次问题排查中，一句话总结问题：prometheus服务会请求tcf-server-demo/tcf-app-backend-test测试服务的/metrics接口，在测试服务处理请求时，会调用到prometheus client_golang开源组件的promhttp/http.go中，处理时会先读取/metrics接口的响应，同时根据handler的配置及请求头的Content-Encoding字段进行判断响应信息是否需要进行压缩处理，刚好在当前版本handler配置中使用的DisableCompression参数为默认值false，且请求头中的Content-Encoding值包含gzip，为此会把响应体作gzip压缩，后续在调用到goframe的server端的trace中间件处理，而该中间件中直接把response body转为string写入到attribute中，这里的response body已经是gzip压缩后的数据，而压缩后的数据不是utf-8类型了，后续grpc server发送数据时，grpc开源组件中会对数据进行utf-8的校验，如果不是标准utf-8类型就会抛出“invalid UTF-8”的错误。大概流程如下：

最终总结这里主要有两个问题：

其一：trace信息的数据获取是批量处理的（应该是性能考虑），如果数据中有一个有问题，可能导致trace信息都export失败；

其二：数据转成pb结构的数据时，如果是其中是gzip过的数据，可能导致marshal失败。

其他：排查问题时还是需要细心，抓住关键点进行排查。遇到不能很方便的debug，同时对一些开源组件源码不熟悉时，最直接有效的方式就是打印相关日志，同时日志打印时需要一定的技巧，先从问题现象处输出日志，再从日志中找关键信息，抽丝剥茧进行分析。分析完成之后可以把怀疑的点进行对比验证，最后找到问题的根因，再选择合适的方案对问题进行修复。