YUAN 2019-07-01
众所周知,日志是记录应用程序运行状态的一种重要工具,在业务服务中,日志更是十分重要。通常情况下,日志主要是记录关键执行点、程序执行错误时的现场信息等。系统出现故障时,运维人员一般先查看错误日志,定位故障原因。当业务流量小、逻辑复杂度低时,应用出现故障时错误日志一般较少,运维人员一般能够根据错误日志迅速定位到问题。但是,随着业务逻辑的迭代,系统接入的依赖服务不断增多,引入的组件不断增多,当系统出现故障时(如Bug被触发、依赖服务超时等等),错误日志的量级会急剧增加。极端情况下甚至出现“疯狂报错”的现象,这时候错误日志的内容会存在相互掩埋、相互影响的问题,运维人员面对报错一时难以理清逻辑,有时甚至顾此失彼,没能第一时间解决最核心的问题。
错误日志是系统报警的一种,实际生产中,运维人员能够收到的报警信息多种多样。如果在报警流出现的时候,通过处理程序,将报警进行聚类,整理出一段时间内的报警摘要,那么运维人员就可以在摘要信息的帮助下,先对当前的故障有一个大致的轮廓,再结合技术知识与业务知识定位故障的根本原因。
围绕上面描述的问题,以及对于报警聚类处理的分析假设,本文主要做了以下事情:
对一段时间内的报警进行聚类处理,将具有相同根因的报警归纳为能够涵盖报警内容的泛化报警(Generalized Alarms),最终形成仅有几条泛化报警的报警摘要。如下图1所示意。
我们希望这些泛化报警既要具有很强的概括性,同时尽可能地保留细节。这样运维人员在收到报警时,便能快速定位到故障的大致方向,从而提高故障排查的效率。
如图2所示,异常报警根因分析的设计大致分为四个部分:收集报警信息、提取报警信息的关键特征、聚类处理、展示报警摘要。
聚类算法采用论文“Clustering Intrusion Detection Alarms to Support Root Cause Analysis [KLAUS JULISCH, 2002]”中描述的根因分析算法。该算法基于一个假设:将报警日志集群经过泛化,得到的泛化报警能够表示报警集群的主要特征。以下面的例子来说明,有如下的几条报警日志:
server_room_a-biz_tag-online02 Thrift get deal ProductType deal error. server_room_b-biz_tag-offline01 Pigeon query deal info error. server_room_a-biz_tag-offline01 Http query deal info error. server_room_a-biz_tag-online01 Thrift query deal info error. server_room_b-biz_tag-offline02 Thrift get deal ProductType deal error.
我们可以将这几条报警抽象为:“全部服务器 网络调用 故障”,该泛化报警包含的范围较广;也可以抽象为:“server_room_a服务器 网络调用 产品信息获取失败”和“server_room_b服务器 RPC 获取产品类型信息失败”,此时包含的范围较小。当然也可以用其他层次的抽象来表达这个报警集群。
我们可以观察到,抽象层次越高,细节越少,但是它能包含的范围就越大;反之,抽象层次越低,则可能无用信息越多,包含的范围就越小。
这种抽象的层次关系可以用一些有向无环图(DAG)来表达,如图3所示:
为了确定报警聚类泛化的程度,我们需要先了解一些定义:
为了计算d(a1, a2),我们先定义两个属性的不相似度。令x1、x2为某个属性Ai的两个不同的值,那么x1、x2的不相似度为:在泛化层次结构Gi中,通过一个公共点父节点p连接x1、x2的最短路径长度。即d(x1, x2) := min{d(x1, p) + d(x2, p) | p ∈ Gi, x1 ⊴ p, x2 ⊴ p}。例如在图3的泛化层次结构中,d("Thrift", "Pigeon") = d("RPC", "Thrift") + d("RPC", "Pigeon") = 1 + 1 = 2。
对于两个报警a1、a2,其计算方式为:
例如:a1 = ("server_room_b-biz_tag-offline02", "Thrift"), a2 = ("server_room_a-biz_tag-online01", "Pigeon"), 则d(a1, a2) = d("server_room_b-biz_tag-offline02", "server_room_a-biz_tag-online01") + d(("Thrift", "Pigeon") = d("server_room_b-biz_tag-offline02", "服务器") + d("server_room_a-biz_tag-online01", "服务器") + d("RPC", "Thrift") + d("RPC", "Pigeon") = 2 + 2 + 1 + 1 = 6。
我们用C表示报警集合,g是C的一个泛化表示,即满足∀ a ∈ C, a ⊴ g。以报警集合{"dx-trip-package-api02 Thrift get deal list error.", "dx-trip-package-api01 Thrift get deal list error."}为例,“dx服务器 thrift调用 获取产品信息失败”是一个泛化表示,“服务器 网络调用 获取产品信息失败”也是一个泛化表示。对于某个报警聚类来说,我们希望获得既能够涵盖它的集合又有最具象化的表达的泛化表示。为了解决这个问题,定义以下两个指标:
H(C)值最小时对应的g,就是我们要找的最适合的泛化表示,我们称g为C的“覆盖”(Cover)。
基于以上的概念,将报警日志聚类问题定义为:定义L为一个日志集合,min_size为一个预设的常量,Gi(i = 1, 2, 3......n) 为属性Ai的泛化层次结构,目标是找到一个L的子集C,满足 |C| >= min_size,且H(C)值最小。min_size是用来控制抽象程度的,极端情况下如果min_size与L集合的大小一样,那么我们只能使用终极抽象了,而如果min_size = 1,则每个报警日志是它自己的抽象。找到一个聚类之后,我们可以去除这些元素,然后在L剩下的集合里找其他的聚类。
不幸的是,这是个NP完全问题,因此论文提出了一种启发式算法,该算法满足|C| >= min_size,使H(C)值尽量小。
算法伪代码如下所示:
输入:报警日志集合L,min_size,每个属性的泛化层次结构G1,......,Gn 输出:所有符合条件的泛化报警 T := L; // 将报警日志集合保存至表T for all alarms a in T do a[count] := 1; // "count"属性用于记录a当前覆盖的报警数量 while ∀a ∈ T : a[count] < min_size do { 使用启发算法选择一个属性Ai; for all alarms a in T do a[Ai] := parent of a[Ai] in Gi; while identical alarms a, a' exist do Set a[count] := a[count] + a'[count]; delete a' from T; }
其中第7行的启发算法为:
首先计算Ai对应的Fi fi(v) := SELECT sum(count) FROM T WHERE Ai = v // 统计在Ai属性上值为v的报警的数量 Fi := max{fi(v) | v ∈ Dom(Ai)} 选择Fi值最小的属性Ai
这里的逻辑是:如果有一个报警a满足 a[count]>= min_size,那么对于所有属性Ai , 均能满足Fi >= fi(a[Ai]) >= min_size。反过来说,如果有一个属性Ai的Fi值小于min_size,那么a[count]就不可能大于min_size。所以选择Fi值最小的属性Ai进行泛化,有助于尽快达到聚类的条件。
此外,关于min_size的选择,如果选择了一个过大的min_size,那么会迫使算法合并具有不同根源的报警。另一方面,如果过小,那么聚类可能会提前结束,具有相同根源的报警可能会出现在不同的聚类中。
因此,设置一个初始值,可以记作ms0。定义一个较小的值 ℇ(0 < ℇ < 1),当min_size取值为ms0、ms0 (1 - ℇ)、ms0 (1 + ℇ)时的聚类结果相同时,我们就说此时聚类是ℇ-鲁棒的。如果不相同,则使ms1 = ms0 * (1 - ℇ),重复这个测试,直到找到一个鲁棒的最小值。
需要注意的是,ℇ-鲁棒性与特定的报警日志相关。因此,给定的最小值,可能相对于一个报警日志来说是鲁棒的,而对于另一个报警日志来说是不鲁棒的。
根据线上问题排查的经验,运维人员通常关注的指标包括时间、机器(机房、环境)、异常来源、报警日志文本提示、故障所在位置(代码行数、接口、类)、Case相关的特殊ID(订单号、产品编号、用户ID等等)等。
但是,我们的实际应用场景都是线上准实时场景,时间间隔比较短,因此我们不需要关注时间。同时,Case相关的特殊ID不符合我们希望获得一个抽象描述的要求,因此也无需关注此项指标。
综上,我们选择的特征包括:机房、环境、异常来源、报警日志文本关键内容、故障所在位置(接口、类)共5个。
我们的数据来源是日志中心已经格式化过的报警日志信息,这些信息主要包含:报警日志产生的时间、服务标记、在代码中的位置、日志内容等。
优先查找是否有异常堆栈,如存在则查找第一个本地代码的位置;如果不存在,则取日志打印位置。
获得故障所在位置后,优先使用此信息确定异常报警的来源(需要预先定义词典支持);如不能获取,则在日志内容中根据关键字匹配(需要预先定义词典支持)。
优先查找是否有异常堆栈,如存在,则查找最后一个异常(通常为真正的故障原因);如不能获取,则在日志中查找是否存在“code=......,message=......” 这样形式的错误提示;如不能获取,则取日志内容的第一行内容(以换行符为界),并去除其中可能存在的Case相关的提示信息
算法的执行,我们以图4来表示。
考虑到日志数据中可能包含种类极多,且根据小规模数据实验表明,min_size = 1/5 报警日志数量时,算法已经有较好的表现,再高会增加过度聚合的风险,因此我们取min_size = 1/5 报警日志数量,ℇ参考论文中的实验,取0.05。
考虑到部分场景下,报警日志可能较少,因此min_size的值也较少,此时聚类已无太大意义,因此设定聚类停止条件为:聚类结果的报警摘要数量小于等于20或已经存在某个类别的count值达到min_size的阈值,即停止聚类。
泛化层次结构,用于记录属性的泛化关系,是泛化时向上抽象的依据,需要预先定义。
根据实验所用项目的实际使用环境,我们定义的泛化层次结构如下:
“故障所在位置”此属性无需泛化层次结构,每次泛化时直接按照包路径向上层截断,直到系统包名。
以下三个实验均使用C端API系统。
实验材料来自于线上某业务系统真实故障时所产生的大量报警日志。
部分原始报警日志如图9所示,初次观察时,很难理出头绪。
经过聚类后的报警摘要如表1所示:
ID | Server Room | Error Source | Environment | Position (为保证数据安全,类路径已做处理) | Summary (为保证数据安全,部分类路径已做处理) | Count |
---|---|---|---|---|---|---|
1 | 所有机房 | 产品中心 | Prod | com.*.*.*.CommonProductQueryClient | com.netflix.hystrix.exception.HystrixTimeoutException: commonQueryClient.getProductType execution timeout after waiting for 150ms. | 249 |
2 | 所有机房 | 业务插件 | Prod | com.*.*.*.PluginRegistry.lambda | java.lang.IllegalArgumentException: 未找到业务插件:所有产品类型 | 240 |
3 | 所有机房 | 产品中心 | Prod | com.*.*.*.TrProductQueryClient | com.netflix.hystrix.exception.HystrixTimeoutException: TrQueryClient.listTrByDids2C execution timeout after waiting for 1000ms. | 145 |
4 | 所有机房 | 对外接口(猜喜/货架/目的地) | Prod | com.*.*.*.RemoteDealServiceImpl | com.netflix.hystrix.exception.HystrixTimeoutException: ScenicDealList.listDealsByScenic execution timeout after waiting for 300ms. | 89 |
5 | 所有机房 | 产品中心 | Prod | com.*.*.*.CommonProductQueryClient | com.netflix.hystrix.exception.HystrixTimeoutException: commonQueryClient.listTrByDids2C execution timeout after waiting for 1000ms. | 29 |
6 | 所有机房 | 产品中心 | Prod | com.*.*.*.ActivityQueryClientImpl | com.netflix.hystrix.exception.HystrixTimeoutException: commonQueryClient.getBusinessLicense execution timeout after waiting for 100ms. | 21 |
7 | 所有机房 | 产品中心 | prod | com.*.*.*.CommonProductQueryClient | com.netflix.hystrix.exception.HystrixTimeoutException: commonQueryClient.getBusinessLicense execution timeout after waiting for 100ms. | 21 |
8 | 所有机房 | 对外接口(猜喜/货架/目的地) | Prod | com.*.*.*.RemoteDealServiceImpl | com.netflix.hystrix.exception.HystrixTimeoutException: HotelDealList.hotelShelf execution timeout after waiting for 500ms. | 17 |
9 | 所有机房 | 产品中心 | Prod | com.*.*.*.TrProductQueryClient | Caused by: java.lang.InterruptedException | 16 |
10 | 所有机房 | 产品中心 | Prod | com.*.*.*.TrProductQueryClient | Caused by: java.lang.InterruptedException | 13 |
我们可以看到前三条报警摘要的Count远超其他报警摘要,并且它们指明了故障主要发生在产品中心的接口。
实验材料为利用故障注入工具,在Staging环境模拟运营置顶服务和A/B测试服务同时产生故障的场景。
部分原始报警日志如图10所示:
经过聚类后的报警摘要如表2所示:
ID | Server Room | Error Source | Environment | Position (为保证数据安全,类路径已做处理) | Summary (为保证数据安全,部分类路径已做处理) | Count |
---|---|---|---|---|---|---|
1 | 所有机房 | 运营活动 | Staging | com.*.*.*.ActivityQueryClientImpl | [hystrix]置顶失败, circuit short is open | 291 |
2 | 所有机房 | A/B测试 | Staging | com.*.*.*.AbExperimentClient | [hystrix] tripExperiment error, circuit short is open | 105 |
3 | 所有机房 | 缓存 | Staging | com.*.*.*.CacheClientFacade | com.netflix.hystrix.exception.HystrixTimeoutException: c-cache-rpc.common_deal_base.rpc execution timeout after waiting for 1000ms. | 15 |
4 | 所有机房 | 产品信息 | Staging | com.*.*.*.queryDealModel | Caused by: com.meituan.service.mobile.mtthrift.netty.exception.RequestTimeoutException: request timeout | 14 |
5 | 所有机房 | 产品中心 | Staging | com.*.*.*.CommonProductQueryClient | com.netflix.hystrix.exception.HystrixTimeoutException: commonQueryClient.getBusinessLicense execution timeout after waiting for 100ms. | 9 |
6 | 所有机房 | 产品中心 | Staging | com.*.*.*.getOrderForm | java.lang.IllegalArgumentException: 产品无库存 | 7 |
7 | 所有机房 | 弹性工程 | Staging | com.*.*.*.PreSaleChatClient | com.netflix.hystrix.exception.HystrixTimeoutException: CustomerService.PreSaleChat execution timeout after waiting for 50ms. | 7 |
8 | 所有机房 | 缓存 | Staging | com.*.*.*.SpringCacheManager | Caused by: java.net.SocketTimeoutException: Read timed out | 7 |
9 | 所有机房 | 产品信息 | Staging | com.*.*.*.queryDetailUrlVO | java.lang.IllegalArgumentException: 未知的产品类型 | 2 |
10 | 所有机房 | 产品信息 | Staging | com.*.*.*.queryDetailUrlVO | java.lang.IllegalArgumentException: 无法获取链接地址 | 1 |
从上表可以看到,前两条报警摘要符合本次试验的预期,定位到了故障发生的原因。说明在多故障的情况下,算法也有较好的效果。
实验材料为利用故障注入工具,在Staging环境模拟产品中心服务和缓存服务同时产生超时故障的场景。
部分原始报警日志如图11所示:
经过聚类后的报警摘要如表3所示:
ID | Server Room | Error Source | Environment | Position (为保证数据安全,类路径已做处理) | Summary (为保证数据安全,部分类路径已做处理) | Count |
---|---|---|---|---|---|---|
1 | 所有机房 | Squirrel | Staging | com.*.*.*.cache | Timeout | 491 |
2 | 所有机房 | Cellar | Staging | com.*.*.*.cache | Timeout | 285 |
3 | 所有机房 | Squirrel | Staging | com.*.*.*.TdcServiceImpl | Other Exception | 149 |
4 | 所有机房 | 评论 | Staging | com.*.*.*.cache | Timeout | 147 |
5 | 所有机房 | Cellar | Staging | com.*.*.*.TdcServiceImpl | Other Exception | 143 |
6 | 所有机房 | Squirrel | Staging | com.*.*.*.PoiManagerImpl | 熔断 | 112 |
7 | 所有机房 | 产品中心 | Staging | com.*.*.*.CommonProductQueryClient | Other Exception | 89 |
8 | 所有机房 | 评论 | Staging | com.*.*.*.TrDealProcessor | Other Exception | 83 |
9 | 所有机房 | 评论 | Staging | com.*.*.*.poi.PoiInfoImpl | Other Exception | 82 |
10 | 所有机房 | 产品中心 | Staging | com.*.*.*.client | Timeout | 74 |
从上表可以看到,缓存(Squirrel和Cellar双缓存)超时最多,产品中心的超时相对较少,这是因为我们系统针对产品中心的部分接口做了兜底处理,当超时发生时后先查缓存,如果缓存查不到会穿透调用一个离线信息缓存系统,因此产品中心超时总体较少。
综合上述三个实验得出结果,算法对于报警日志的泛化是具有一定效果。在所进行实验的三个场景中,均能够定位到关键问题。但是依然存在一些不足,报警摘要中,有的经过泛化的信息过于笼统(比如Other Exception)。
经过分析,我们发现主要的原因有:其一,对于错误信息中关键字段的提取,在一定程度上决定了向上泛化的准确度。其二,系统本身日志设计存在一定的局限性。
同时,在利用这个泛化后的报警摘要进行分析时,需要使用者具备相应领域的知识。
本文所关注的工作,主要在于验证聚类算法效果,还有一些方向可以继续完善和优化: