如何利用日志快速定位问题
引言
一般来说软件系统或者软件组件都可以简单的划分为下面三部分:
-
输入部分,例如:
-
软件系统外部通信数据/事件输入;
-
软件组件API接口参数(同步/异步);
-
-
-
处理部分,例如:
-
软件系统或者组件内部处理(比如:状态机处理);
-
-
输出部分,例如:
-
软件系统输出到外部的通信数据;
-
软件组件调用其他组件API;
-
软件系统或者组件写数据到外部(存储设备,网络设备,文件,共享内存,数据库等)
-
为了方便定位问题,上面每一部分都需要覆盖"不多不少"的日志才行。一般来说,输入输出必须加入详细的日志,方便快速界定问题的所属,甚至重现问题;处理部分中关键动作、主要分支、重要入口、预期不会发生的情况,都必须加入详细的日志,方便定位问题;
日志是设计的产物
一方面由于日志的受众有不同的群体,生产工程师,测试工程师,技术支持,开发工程师等,故日志应该具有不同的抽象层次,"ECall is trigger"这句日志打印对生产工程师,测试工程师是友好的,他们完全明白发生了什么事情,"ECallSts = 0"这句日志恐怕只有开发工程师明白发生了什么事情。故我们应该在设计阶段就定义好高抽象度,而且目标受众是非开发工程师的日志,将这些日志作为设计的一个成果物。原因如下:
-
参与上流设计的工程师都是精英工程师,他们有能力定义足够抽象的日志;
-
设计阶段就应该考虑怎么验证我们的系统,日志作为验证设计的一种手段,就应该在设计阶段被考虑;
-
上流设计工程师通过预定义好最少日志,在项目后期也方便验证系统实现是否按照预期实现;
另一方面,软件中出现的错误我们可以分为两类,一类是设计阶段就预估到了的,还有一类是由于能力有限设计阶段没有预估到,设计阶段就预估到的错误我们需要设计相应的日志来覆盖。
总的来说,在设计阶段设计好接口类(输入&输出)日志 & 运行类日志(关键动作&主要分支&重要入口&预期不会发生的情况等)日志内容,在实现阶段不断完善调试类日志内容。需要强调的是,好的调试类日志,绝不是一遍就可以写好的,因此团队要重视日志优化这件事情,不要让日志的质量持续降低(当项目变大时,项目的代码也存在一样的问题,越写越乱)。
-
在定位问题的过程中完善日志,如果定位问题花费了很长时间,那就说明日志还存在问题,需要进一步完善和优化;
-
需要思考是否可以通过优化日志,来提前预判该问题是否可能发生(如某种资源耗尽而导致的错误,可以对资源的使用情况进行记录)
-
定义好整个团队记录日志的规范,保证每个开发记录的日志格式统一;特别需要说明的是,对于DEBUG级别的日志,也需要定义好清晰的格式,而不是由开发人员自由发挥;
-
整个团队定期对记录的日志内容进行Review;
日志怎么设计
日志内容格式
实际项目中日志框架都会包含时间、进程ID、线程ID、级别、模块名等通用信息,但对日志内容却没有严格的限制。日志内容应该考虑可读性与全局唯一性,符合人的理解。
-
日志格式:采用 主语+谓语+宾语+状语 的格式,日志打印遵从人类的自然语言:
-
主语:会话的发起者
-
谓语:将要具体进行什么样的操作
-
宾语:行为对象
-
状语:行为产生的结果
例如: "TBox trigger ECALL successful“
-
-
可读性:不打无用的、无意义、不完全的日志,例如不是打印 “Unknown message type”,而是打印 “Unknown message type,type= , supported types=[A,B,C]”
-
安全性:避免在日志中输出一些敏感信息,例如密码与Key等;
-
全局唯一性:日志内容应该全局唯一,方便ctrl+f全局查找。
-
信息充足性:在实践中经常发生日志不够的情况,在输出日志时,要注意一并输出上下文相关信息,比如函数的入参,函数返回值,内部主要数据等。同时也要注意日志内容不宜太长,最好显示在一行内(最多50个字符)
日志等级划分
一般来说,日志等级分为五种级别,从高到低分别是:FATAL,ERROR、WARN、INFO、DEBUG:
-
FATAL:系统已经无法正常工作,属于最严重的日志级别,一般来说应该非常少见。比如
-
引发整个系统失败的错误发生了;
-
系统无法正常启动;
-
某个进程遇到无法恢复的错误而自动退出;
-
关键组件启动失败;
-
-
ERROR:系统部分功能已经无法正常使用,紧急程度要低于FATAL级别。比如:
-
调用外部系统接口返回失败,重试多次后依然失败;
-
系统资源使用(RAM,CPU)超过预期;
-
-
WARN:不会影响程序继续执行后续的逻辑,更多是一种重要提示需要引起重视。程序可以容忍这些信息,不过它们应该被及时地检查及修复。比如:
-
组件输入输出异常时需要打印(API参数值异常/同步API返回值异常/异步事件超时);
-
备份数据恢复出错,采用默认备份数据;
-
-
INFO:记录系统的正常运行状态,通过查看INFO级别的日志,方便很快地对系统中出现的WARN,ERROR,FATAL错误进行定位。比如:
-
组件相关信息打印(组件初始化完成了/正常输入输出/内部状态机发生迁移/主要分支入口/主要操作成功了/异步请求执行结果输出)
-
系统操作行为:如开启/销毁线程,打开/关闭连接,定时任务触发等;
-
资源或状态变化:系统初始化成功,关键资源的统计信息;
-
非预期执行:为程序在“有可能”执行到的地方打印日志,如switch case语句块中的default;
-
-
DEBUG:该级别日志的主要作用是对系统每一步的运行状态进行精确的记录。通过该种日志,可以查看某一个操作每一步的执行过程,可以准确定位是何种操作,何种参数,何种顺序导致了某种错误的发生。可以保证在不重现错误的情况下,也可以通过DEBUG(或TRACE)级别的日志对问题进行诊断。比如:
-
方便CT & IT测试添加的日志
-
非API函数的入参打印
-
快速定位
如前面所说,系统或者组件一般可以分为三部分,输入->处理->输出。故在调查具体的bug时,我们需要能知道以下信息:
-
本软件系统/本软件组件输入输出是否正常;
-
如果输出不正常,到底是输入异常导致 OR 软件系统或者组件处理出错导致;
-
如果是系统或者组件内部出错,要能通过日志定位到具体原因。
-
鉴于bug很多都是时序混乱、数据非法等造成的,故需要通过日志快速知道问题发生时各组件交互时序,系统/组件输入数据是否非法等。
在以往的项目中经常遇到这个问题,几乎总有人会在问题发生时说,这个日志基本上没有什么用处/或者这个日志我不知道想要干什么,但是每个人似乎又不能说出具体日志应该怎么输出才对。 故能否像MISRC规范对代码提出一些硬性要求一样,对日志也制定一些最低要求。
===================================================================================================================================
- FSR1 [强制]:项目团队要制定日志输出规范.
- FSR2 [强制]:项目团队要制定日志评审流程。
- FSR3 [强制]:设计阶段设计好日志(边界类&运行类日志)。
- FSR4 [建议]:设计阶段设计用于系统测试&结合测试的日志。
- FSR5 [强制]:系统的输入输出,必须覆盖详细的日志,日志中包含输入或者输出的一些关键参数。
- FSR6 [强制]:组件的输入输出,必须覆盖详细的日志,日志中包含输入或者输出的一些关键参数。
- FSR7 [强制]:组件必须至少包含以下4种关键词的日志,用来诊断组件是否健康。
- FSR7.1 [强制]:程序流关键分支上打印用一种关键词,通过筛选该关键词能快速定位问题出现在那个时序段。
- FSR7.2 [强制]:设计时考虑不可能发生的分支上打印用一种关键词,通过筛选该关键词能快速是否进入了以为不可能进入的分支。
- FSR7.3 [强制]:函数入参范围检查不合格打印用一种关键词,通过筛选该关键词能快速知道是否函数入参超过范围。
- FSR7.4 [强制]:组件输入输出打印用一种关键词,通过筛选该关键词能快速知道组件是否正常。
- FSR7.5 [强制]:上述4种关键词在所有组件都是相同的。
- FSR8 [建议]: 日志内容总体上来说要尽可能少(不意味着信息缺失),方便快速分析。
- FSR9 [强制]: 日志内容要包含时间戳,日志等级,模块名等关键词方便快速筛选。
- FSR10 [建议]: 错误之处覆盖的日志要包含上下文相关信息(函数的入参/函数返回值/内部主要数据值等)。
- FSR11[强制]: 不循环打印相同内容日志。
- FSR12[强制]: 每行日志内容不宜过长,不超过50字。
- FSR13[建议]: 日志内容要遵守上述日志内容输出格式。
- FSR14[强制]: 日志登记要遵守上述日志等级划分要求 。
- FSR15[强制]: 系统版本号/各部件版本号/数据库版本号等相关版本信息需要以最高等级输出。