trace信息采集失败问题分析
背景
随着大量云原生技术的应用，IT系统日益复杂，开发人员经常会遇到类似的问题场景：
页面超时，到底是哪个服务的请求慢，请求慢的具体原因是啥；
如何快速了解服务的处理能力，包括TPS、QPS等；
线上服务部署了多个pod，如何快速查看相关的错误日志。
在业务上遇到问题时，如何才能做到主动感知、预测故障、迅速定位呢？传统的监控方式已经跟不上现有需求了，为此可观测性应运而生。而metrics（指标）、tracing（调用链）、logging（日志）是可观测性的三大支柱，其主要特点为：
metrics：提供量化的系统内/外部各个维度的指标，包含Counter、Summary、Gauge、Histogram等，主要特征是可聚合性，可以非常方便的了解业务的实时情况；
tracing：提供一个请求从接收到处理完毕整个生命周期的跟踪路径，通常请求是在分布式系统中，可以根据traceId和spanId了解一次请求的完整链路；
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文件也都正常可用。
测试过程中，包含三个服务
tcf-app-backend-pro：主要包含了一些db的操作，接入了otel-collector，未接入prometheus；
tcf-server-demo：用来启动grpc服务端、rpc服务端、kafka生产端，每隔30s kafka会生产一条消息，接入了otel-collector和prometheus；
tcf-app-backend-test：用来做客户端和kafka消费端的操作，该服务中每隔30s kafka会消费一条消息、redis中会lpush一条数据、触发一个http请求www.baidu.com，触发一个grpc请求、触发一个rpc请求，同时也接入了otel-collector和prometheus；
关系图如下：
开发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 checkreturn 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.Formatif 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 greetingrpc 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.Buffergz := 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，同时对一些开源组件源码不熟悉时，最直接有效的方式就是打印相关日志，同时日志打印时需要一定的技巧，先从问题现象处输出日志，再从日志中找关键信息，抽丝剥茧进行分析。分析完成之后可以把怀疑的点进行对比验证，最后找到问题的根因，再选择合适的方案对问题进行修复。
三七互娱技术团队
扫码关注 了解更多