BBS-GO Community

Go My Way #3 - Tracing

蒋载休2020-06-04 10:10

Go My Way是用3篇文章介绍使用Go语言时，我比较喜欢的方式。
如果没看之前的文章可以参考下面的链接。

这篇文章介绍追踪。

现在我们的云服务里有500多个微服务在运行。
用户的一个请求需要通过多个微服务的之间的配合返回给最终结果。
处理过程中因业务需求产生事件，consumer service接受事件后处理多个事项。

microservice

EventBroker publish 事件和subscription 的一系列操作的服务。内部是使用kafka传达事件。基本的事件传达功能以外调整consume service之间的balance, loggin, offset 等等的管理。

运营了1年多的微服务的环境，发现和以前的monolitic方式比起来，有不一样的痛点。

有什么问题?

很难追踪问题

就凭着nginx的access log和开发者自己留的日志判断这些问题越来越困难了。

  • 上面所述的复杂的流程中，A服务是正常，但是C服务器宕机。
    是程序问题？网络问题？哪里超时了？
  • 接受事件的D服务宕机，我们如何知道出问题了？
    我的服务没问题(我自己写的当然没问题) kafka没处理好事件？

同事之间相互怀疑，会放弃解决问题。用户使用出现障碍，我们却不能定义哪里出问题。

很难了解整体的业务流程

新写一个新的微服务，其他服务都可以自由的调用。
每当定义好一个行为事件，需要的服务就subscribe 该事件后延伸业务。
这时好几个组开发的服务项目调用完成一个请求。
所以就很难彻底的了解，当用户点击一个按钮的时候发生的会发生什么事情。
一个微服务的小小变化引起的影响度无法预测。

以前想了解业务流程，一行一行的去看代码就可以，
但是像现在多个微服务之间的相互作用来完成一个功能的环境下，
如果不能明确微服务之间的关系就很难清晰的整理业务逻辑。

嗯... 有可能会发生连我们都不知道给顾客提供的功能是怎么运作的。

找不到瓶颈是在哪里发生

用户也没有增多，服务器资源也很充足，请求反应时间也有可能会变慢。
瓶颈是在哪里呢？

需要trace系统

所以我们需要记录所有服务的行为日志。而且要透明的展示。

最有代表性的解决方案是有zipkin, lightstep, appdash 还有使用, opentracing的话可以很方便的信息传送到trace服务。这比较全面(?)的解决方案是可以直接安装使用，但是实际运营的时候会遇到一些问题。
大致的可以分2各类型的问题。

  • 有太多的功能
    所以需要学习的内容也多，其实我们需要的功能是解决方案里面的一小部分功能。
    华丽的UIR和简介的 Getting Started文件的诱惑虽然很大，但是想用到我预期的目标，需要学很多内容。
    而且学习这些特定的解决方案感觉有点喧宾夺主的感觉。

  • 没有我们真正需要的功能
    虽然提供很多功能，但是不是我们想要的功能是有一些差距的。
    所以我们还是需要customizing后使用，这过程消耗很多资源和时间。

新引进一个解决方案，开始的时候有可能不太了解该解决方案的解决问题的思维方式。
这些方案是为了解决某些问题，尝试了很多方案以后，优化好的功能。
不知道这些过程只使用结果的话，一般情况下结果是一般般的。
所以一开始的时候需要自己一步一步的去构建后，对那些方案有充分的了解和认可的时候使用的才能出来比较好的结果。

基于这些原因，我们自己构建了trace环境。

留Behavior log

为了区分ngnix里记录的accesslog，我们把各自微服务记录的trace信息叫behaviorlog。
ngnix里记录的accesslog是使用者请求记录的话，behavior log是我们为了查看云内部的行为留的日志。

behaviorlog是如以下方式记录。

behavior log 如何识别

  • SessionID
    普通的Web开发中session是为了维持服务和客户端，用户信息存放在服务的一种方法。
    我们是使用JWT的认证方式。
    JWT本身包含着用户信息，所以我们不需要使用其他方式保存。
    那这SessionID是?
    不是指特定技术的名字，是代表一个用户登录以后到退出这一过程的所有事件的捆绑。
    对我们来说Session是 发放的JWT tokende 使用期限。
    在前面也讨论过JWT token的结构，我们就把JWT token 的最后一部分的签名(Sinature)的部分存到Session这一栏里面。
    也就是说登录以后获取的JWT token的所有事件都是同一个Session的行为。
  • RequestID
    使用者的一个请求的所有的事件是都包含着相同的RequestID。
  • ActionID
    各微服务的函数都会有固有的ActionID。
  • ParentActionID
    调用我的caller服务的ActionID是 ParentActionID

SessionID, RequestID, ActionID, ParentActionID 使用者4个概念就可以详细的表达出一个请求的过程。

tracing

以下是所有的微服务需要遵守的规则。

  1. nginx接受外部请求后，创建新的 RequestID放到Header的 X-Request-ID。
    (参考：ngx_http_core_module.html#var_request_id)
  2. 各服务队每次请求新建一个 ActionID。
  3. 调用其他服务时把RequestID和自己的 ActionID放到 Header的 X-Request-ID, X-Action-ID
  4. 各服务请求处理结束后，日志传送到kafka(topic: behaviorlog)
    log 标识符:
    • SessionID: JWT token的 签名(Sinature)部分
    • RequestID: Header的 X-Request-ID
    • ActionID: 自己创建的标识符
    • ParentActionID: Header的 X-Action-ID

处理上述功能的代码如下。
代码是以[#1 - Web Framework]说明的的 echo 框架为基础说明的。

func main() {
	e := echo.New()
	/* ... */
	e.Use(BehaviorMiddleware)

	if err := e.Start(":8080"); err != nil {
		log.Println(err)
	}

}

func BehaviorMiddleware(next echo.HandlerFunc) echo.HandlerFunc {
	return func(c echo.Context) (err error) {
		req := c.Request()

		requestId := req.Header.Get("X-Request-ID")
		actionId := random.String(32)
		parentActionId := req.Header.Get("X-Action-ID")

		defer func(begin time.Time) {
			logrus.WithFields(logrus.Fields{
				"request_id":       requestId,
				"action_id":        actionId,
				"parent_action_id": parentActionId,
				"timestamp":        begin.UnixNano(),
				"latency":          time.Since(begin).Nanoseconds(),
				"error":            err,
				/* ... */
			}).Info()
		}(time.Now())

		/* ... */

		err = next(c)

		/* ... */
		return
	}
}

但是我们需要解决的问题不止这些。
不仅是Request请求的处理情况，处理过程中也需要留日志。
这些日志也要有RequestID, ActionID, ParentActionID才能能了解整体情况。
(需要查看所有日志的前后才有意义。）
然后Web Request 的基本信息以外，逻辑上需要留的信息也需要一球存。(例: Session的使用者ID, 参数，以及处理结果等等...)
所以只用中间层的功能是不够的。

LogContext

处理Request的过程中 context.Context里有log内容的 LogContext。
如果想添加log，可以使用context.Context里的LogContext留日志。

type LogContext struct {
	ParentActionID string    `json:"parent_action_id"`
	ActionID       string    `json:"action_id"`
	RequestID      string    `json:"request_id"`
	Timestamp      time.Time `json:"timestamp"`
	Service        string    `json:"service"`

	Params     interface{}            `json:"params,omitempty"`
	Controller string                 `json:"controller,omitempty"`
	Action     string                 `json:"action,omitempty"`
	BizAttr    map[string]interface{} `json:"bizAttr,omitempty"`
	Err        error                  `json:"error,omitempty"`

	/* ... */
}

LogContext的所有代码 [behaviorlog.go]可以参考(https://github.com/pangpanglabs/goutils/blob/master/behaviorlog/behaviorlog.go)

context.Context是等待处理完一个Request的过程中一直维持scope, 所以处理一个请求的时候通过 LogContext留日志的话会有相同的 RequestID, ActionID。
所以留所有日志的 RequestID, ActionID, 通过这些我们可以推算这个过程。

留日志的代码如下。

BehaviorLogger(ctx).
    WithBizAttr("userID", currentUser.ID).
    Log("SearchDiscount")

func BehaviorLogger(ctx context.Context) *behaviorlog.LogContext {
    v := ctx.Value(behaviorlog.LogContextName)
    if logger, ok := v.(*behaviorlog.LogContext); ok {
        return logger.Clone()
    }
    return behaviorlog.NewNopContext()
}

中间层使用LogContext留日志的方法如下。

func BehaviorMiddleware(serviceName string) echo.MiddlewareFunc {
    return func(next echo.HandlerFunc) echo.HandlerFunc {
        return func(c echo.Context) (err error) {
            req := c.Request()
            behaviorLogger := behaviorlog.New(serviceName, req)

            // behaviorLogger를 context.Context에 담음
            c.SetRequest(req.WithContext(
                context.WithValue(req.Context(),
                    behaviorlog.LogContextName, behaviorLogger,
                )))

            if err = next(c); err != nil {
                c.Error(err)
                behaviorLogger.Err = err
            }

            /***
             ...
            **/

            behaviorLogger.Write()
            return
        }
    }
}

Behavior log和相关的代码可以通过下面的链接确认。

调用其他服务

前面提到调用微服务的时候把自己的 RequestID和 ActionID放入Heather。
虽然不难但是比较法索，为了方便我们做了一个公用包。 github.com/pangpanglabs/goutils/httpreq
调用其他微服务的时候使用httpreq 包。

var v ApiResult
statusCode, err := httpreq.New(http.MethodPost, "TARGET_URL", param).
    WithRequestID("requestID-1").
    WithActionID("actionID-1").
    Call(&v)

或

var v ApiResult
statusCode, err := httpreq.New(http.MethodPost, "TARGET_URL", param).
    WithBehaviorLogContext(behaviorlog.FromCtx(ctx)).
    Call(&v)

调用外部API

调用的对象不服务如果是用相同的方式留Behavior log的话Trace信息不会断开。
但是有时候很难把Behavior log留到对象服务。
举例子使用快递公司的api是必掉典型的事项。这时候日志流程不太完整。

像这样不是我们领域调用外部API的时候，Behavior log是在我们这里调用的时候留日志。

BehaviorLogger(ctx).
    WithBizAttr("companyCode", "MY_COMPANY_CODE").
    WithCallURLInfo(http.MethodGet, "TARGET_URL", param, 200).
    Log("GetShippingStatus")

安全的日志存储库

所有的追踪日志是通过kafka留到HDFS。
通过能在不同的数据库执行的 SQL Engine的 Presto我们可以查看需要的信息。

trace-hdfs

活用追踪日志，我们可以做多样的视觉效果图。
如下的是解决效果图，可以实时查看使用者发出请求是通过哪些流程处理。

评论

请登录后发表观点

暂无数据