作者：simonyzhao   赵军岩

编辑：mavisxlmeng  蒙雪莲

1

背景

随着微保业务和技术的发展，也对系统日志输出制定了更严格的规范，要求线上系统减少不必要日志的输出，比如开发过程当中的调试日志，并且能够逐步将系统日志级别从debug调试级别上调到warn警告级别，甚至error错误级别。

然而面对线上环境用户反馈的一些问题，有些场景下，仅靠warn、error级别的日志，可能无法分析定位到问题的原因。线上问题可能是某个特定用户的问题，也可能是某个业务的问题，为了能够快速解决线上问题，需要对问题相关日志进行染色。

本文主要介绍下微保自研的MSF-Go微服务框架在日志染色方面的思考与实践。

2

日志模块简介

为了能够更好地理解日志染色的实现，先简单介绍下日志模块的功能。最初的日志模块实现了诸如日志分级、日志滚动、日志采样、日志位置输出等基本功能，并支持终端、单文件、多文件等类型输出。

2.1 日志分级

为了方便查阅日志，首先对日志进行了分级，包括debug、info、warn、error、fatal等5个级别，并按顺序依次升高，它们分别对应了5个日志文件，每个级别的日志需要调用相应的接口进行输出，如下表所示：

为了提高在服务器上查阅日志的效率，特别是在节点数比较少、日志全部输出的测试环境，最初采用了漏斗方式输出的设计，即高级别的日志信息会输出到低级别的日志文件中，比如warn级别的日志信息除了会输出到warn级别的日志文件中之外，还会输出到debug、info级别的日志文件中，如下图所示，warn级别日志会流经debug、info止于warn。

漏斗方式的设计，能够使得在debug级别的日志文件中能够查阅到所有级别的日志，这对于在服务器上查阅日志要方便很多，特别是测试环境，定位问题时不用在多个日志文件之间来回切换。

2.2 日志滚动

为了防止单个日志文件过大，日志模块支持按照日志文件大小对日志进行滚动，同时也支持按天进行滚动，方便根据时间查看日志。日志按天和大小滚动都支持自定义配置，默认同时生效，日志文件如下表所示，没有带后缀的文件表示是当前正在写入的文件：

2.3 日志采样

为了防止日志输出数量过大，日志模块也具有流控功能，通过采样输出实现，支持自定义开启或者关闭，默认关闭。日志级别相同且内容也相同的日志会被认为是同一条日志，内容是指要输出的有效文本信息，如下标红的部分所示，其他格式化的信息不包含在内。

该功能实现的效果是在每个周期Tick内，如果同一条日志的输出数量超过了限流阈值Initial后，那么超过的部分，每隔Thereafter的数量，才会再输出一次。上面提到的3个重要参数如下：

1) 周期（Tick）：从输出第一条日志开始计时，计数器会对同一条日志进行计数，到达一个周期后，无论是否能够达到限流阈值Initial，计数器都会被置零，并重新开始计数；

2) 限流阈值（Initial）：在一个周期Tick内，当计数器对同一条日志的输出计数达到了限流阈值Initial时，会触发限流，超过的部分将根据间隔数值Thereafter的设置进行输出；

3) 间隔数值（Thereafter）：触发限流后并不是完全不再输出日志，而是每隔Thereafter的数量才输出一次，直到本周期Tick结束。

举例：假设周期Tick为1秒，限流阈值Initial和间隔数值Thereafter都是100，那么1秒内同一条日志超过100条后触发限流，之后每100条日志仅输出1条，直到进入下一个周期Tick重新计数。

通过日志采样，降低了服务在高并发下输出日志的开销，能够有效提升服务的吞吐能力，由于触发限流后并非完全不输出日志，所以在业务出现故障的时候也能保留一部分日志来支撑问题定位。

此外该功能还有一个作用，当线上突然出现大量错误时，大多数情况下都来源于同一个错误，日志监控服务会将错误日志推送到企业微信告警群，每个企业微信群都有额度限制，采样功能还能够降低额度消耗，避免额度被快速用尽。

2.4 日志位置输出

为了方便快速定位到输出日志的代码位置，日志模块支持在日志里面记录该信息，即文件名及行号等信息。为了确保日志简洁，只输出文件所在的当前目录和行号，比如“model/msg.go:58”。

为了方便使用，日志模块提供了两种日志输出的接口，以info级别日志举例，输出接口如下，其中后台服务之间rpc调用的公共信息采用上下文context进行传递：

（1）log.Infof(format string, v ...interface{})

（2）log.With(context  context.Context).Infof(format string, v ...interface{})

对于仅需要记录一些简单的日志信息，比如一些提示日志，并不会用于问题定位，可以采用第一种方式输出；如果需要输出context里面的公共信息以方便问题定位，比如用户id、追踪id等，可以采用第二种方式输出，这也是框架建议的输出方式。为方便后文引用描述，第一种方式称为简量输出，第二种方式称为全量输出。

3

思路

首先需要思考，日志染色要解决的是什么问题。在生产部署中，日志规范要求系统日志级别逐步上调到warn、error级别，如下图绿色部分所示；当线上环境出现问题时，现有warn、error级别的日志不足以支撑问题定位的情况下，警告级别以下未能输出的日志将对排查问题起到重要作用。此时需要能够输出尽量少的日志，但是能够包含所有涉及的服务包括debug、info级别在内的相关全量日志，即这些日志仅属于问题相关的日志，如下图浅黄色部分所示，并且能够搜索分析，快速定位问题。当前日志模块现有的功能并不能很好的解决该需求，所以需要对线上问题整条链路的相关日志进行染色。

3.1. 缩写简介

• openid：在微信生态内，每一个公众号或者小程序下，微信对同一个用户生成的唯一身份标识；

• userid：在微信生态内，为了关联同一个用户，微保给用户生成了一个统一的userid，即在微信生态内，同一个用户只会有一个微保的userid，却会有多个微信的openid；对于非微信生态的H5环境，微保也会给用户生成一个H5环境的userid。

3.2. 方案

业务现况催生需求，需求催生方案。如果某一个用户仅在某个公众号或者小程序出现异常需要查询日志，而且只是个例，其他用户并没有异常，那么只需要对该用户的openid进行染色即可，保证日志染色的最小集合；如果某一个用户在公众号和多个小程序之间出现异常需要查询日志，此时在不同环境下该用户的openid会发生变化，仅通过染色openid可能无法查出问题，此时需要对该用户的userid进行染色，或者是在用户只有userid没有openid的H5环境也只能对用户的userid进行染色；此外，如果某个业务的某个功能有多个用户反馈了问题，那么常常需要对该功能经过的整条链路进行染色。

如上图所示是一个用户请求的简易流程，用户在微保官方平台的请求经过接入层网关转发到后台服务，对于日志染色，需要考虑以下问题，上图中的编号与下面的编号是一一对应关系：

① 染色类型：需要根据场景对用户的openid、userid或者整条链路进行染色；

② 信息透传：为了方便使用，框架层封装了日志染色细节，但是需要在调用下游后台服务时透传含有染色信息的上下文context，并在输出日志时采用全量输出方式，即需要带上context，以方便框架层解析出染色信息，如果采用简量输出方式，那么该日志将不会被染色；

③ 开关：日志染色的开关应该是随开随关的，所以系统并不是在初始化时确定日志染色的开关，而是在日志写入时才会确定，方便在需要使用的时候随时打开，不需要使用的时候随时关闭；

④ 染色关键字：对于染色的日志，需要能够进行搜索分析，为此定义了每种类型的关键字，染色的英文是dye，故采用了dye+染色场景的组合来命名，比如对用户openid进行染色的关键字为dye. openid，对用户userid进行染色的关键字为dye.userid，对整条链路进行染色，需要先在警告或者错误日志里面找到染色关键字，比如dye.message-center.GetMsg，该关键字会一直存在于采用全量输出方式的日志里面，同时该关键字也被当做请求进入接入层网关的唯一路由标识；

⑤ 全量输出：正常日志具有的特性染色日志也同样具有，比如按大小滚动、按天滚动、日志采样、日志位置输出等，同时支持自定义配置输出级别，默认是debug级别，即染色日志会输出到debug日志文件中，同时染色日志会忽略当前日志debug、info的级别，以配置的级别为准进行全量输出；

⑥ 搜索分析：日志文件会被自动采集和汇总，打开日志染色开关后，就可以在日志查询平台通过上述的染色关键字进行搜索和分析。

以上问题考虑清楚之后，方案也自然成形，将染色开关、染色类型、输出日志文件等级做成配置化，在用户请求经过接入层网关的时候，如果该请求需要染色，接入层网关会把染色信息放入上下文context透传给后台服务，在输出日志时从context解析出染色信息对日志进行染色。

3.3. 实现

• 配置平台 首先需要一个配置平台将染色开关、染色类型、输出日志文件等级等做成配置化，同时有一个数据库进行保存这些配置，方便在需要的时候随时配置使用，配置信息如下图所示：

  
  

• 使用方式 在调用下游服务的时候需要将context透传下去，保证一个请求的整条链路中都携带染色的配置信息，同时输出日志时采用全量输出方式。

• 染色流程 接入层网关会定期拉取更新需要染色的配置信息，放到内存中以备使用。对于不需要染色的请求，会把唯一路由标识放到context里面，比如dye.message-center.GetMsg，可以直接在日志中获得。

  当用户访问微保相关平台时，如小程序、公众号或者H5，当请求经过接入层网关时，接入层网关会检测该请求是否需要染色，如果需要染色，接入层网关除了将头部信息转化为上下文context之外，还会将染色信息也会放到context中，然后透传给后台服务，该带有染色信息的context会在整条链路调用中一直透传下去，在框架层和业务层的采用全量输出方式的日志会自动染色，日志会被自动采集汇总，然后在日志查询平台通过染色关键字进行查询和分析问题。

  整个染色流程如下图所示，对于红色实线箭头相连的服务，它们输出的染色日志都会被日志查询平台采集和汇总，包括接入层网关、服务B1、服务A2、服务C2、服务A3和服务C3，为了流程图的简洁，采集和汇总的虚线箭头仅连接了服务C2和服务C3：

  
  

3.4 效果

当服务正常运行时，日志情况如下图所示，可能全部没有日志，也可能会在服务初始化时输出一些提示日志，服务运行情况可以通过监控视图查看，此处不再赘述。

当服务运行中出现警告或者错误日志时，warn、error级别的日志文件中会有相关信息，如果根据warn、error级别的日志无法定位到问题原因，那么可以在配置平台打开染色配置，如下图所示，日志级别设置到info，那么系统的debug、info级别的日志都会输出到info级别的日志文件中。

然后去日志查询平台根据关键字查询，比如使用染色关键字“dye.evaluatehe

ad-service”可以搜索出所有被染色的日志，同时也可以增加其他关键字进行更精细的搜索，如下图所示，采用了"dye.evaluatehead-service" 和“456404f9”两个关键字进行搜索，这样可以更快速定位到问题原因，问题解决之后关闭染色配置即可。

4

小结

通过对线上实际情况的分析，目前的染色类型已经基本可以满足日常查询问题的需求，该功能目前还在灰度过程当中，在未来全量推进后还会根据线上具体情况不断进行演化，以更好地应对新的需求。

日志染色是日志模块里面很重要的一块拼图，它解决了整条链路的日志输出问题，该功能对于请求不经过接入层网关的情况、以及服务间调用时context没有规范透传下去的情况并不奏效，为了解决该问题，日志模块支持了服务维度的日志等级动态调整，允许为了定位问题，申请临时下调日志级别，两者相辅相成，能够更好的支撑线上问题定位。同时线上环境也会做服务维度的debug、info级别的日志监控，避免无节制的使用。

除此之外，日志模块还增加了一些其他的功能，比如为了降低日志输出对服务性能的影响，在同步输出的基础之上增加了对异步输出的支持，服务可以根据具体场景灵活选择输出方式；比如日志染色的出现，完全可以使用染色关键字加其他关键字的方式通过日志查询平台查询日志，加上服务节点日趋增加以更好地应对日益增加的业务流量，相比之下在服务器上查询日志的效率会越来越低，同时为了降低日志存档的存储成本及简化采集逻辑，最初漏斗输出的方式改成了现在独立输出的方式，即info级别的日志仅会输出到info级别的日志文件中，这样日志文件变小了，日志采集时也不需要考虑重复采集的问题；再比如为了统一日志输出格式，对不同语言进行了统一的规范等。

本文的染色方案是基于现有业务碰到的问题而提出的，目的是为了规范日志输出的同时，兼顾线上环境出现问题的时候，能够帮助开发人员快速定位问题，过程中也有我们自己的一些思考，希望能给大家带来一些帮助。