如何利用日志快速定位问题

如何利用日志快速定位问题

引言

一般来说软件系统或者软件组件都可以简单的划分为下面三部分：

• 输入部分，例如:

  • 软件系统外部通信数据/事件输入；

  • 软件组件API接口参数(同步/异步)；

  • 软件系统或者组件从外界读取数据(存储设备，文件，共享内存，数据库等)

• 处理部分，例如：

  • 软件系统或者组件内部处理(比如：状态机处理)；

• 输出部分，例如：

  • 软件系统输出到外部的通信数据；

  • 软件组件调用其他组件API；

  • 软件系统或者组件写数据到外部(存储设备，网络设备，文件，共享内存，数据库等)

为了方便定位问题，上面每一部分都需要覆盖"不多不少"的日志才行。一般来说，输入输出必须加入详细的日志，方便快速界定问题的所属，甚至重现问题；处理部分中关键动作、主要分支、重要入口、预期不会发生的情况，都必须加入详细的日志，方便定位问题；

 

日志是设计的产物

一方面由于日志的受众有不同的群体，生产工程师，测试工程师，技术支持，开发工程师等，故日志应该具有不同的抽象层次，"ECall is trigger"这句日志打印对生产工程师，测试工程师是友好的，他们完全明白发生了什么事情，"ECallSts = 0"这句日志恐怕只有开发工程师明白发生了什么事情。故我们应该在设计阶段就定义好高抽象度，而且目标受众是非开发工程师的日志，将这些日志作为设计的一个成果物。原因如下：

1. 参与上流设计的工程师都是精英工程师，他们有能力定义足够抽象的日志；

2. 设计阶段就应该考虑怎么验证我们的系统，日志作为验证设计的一种手段，就应该在设计阶段被考虑；

3. 上流设计工程师通过预定义好最少日志，在项目后期也方便验证系统实现是否按照预期实现；

另一方面，软件中出现的错误我们可以分为两类，一类是设计阶段就预估到了的，还有一类是由于能力有限设计阶段没有预估到，设计阶段就预估到的错误我们需要设计相应的日志来覆盖。

总的来说，在设计阶段设计好接口类(输入&输出)日志 & 运行类日志（关键动作&主要分支&重要入口&预期不会发生的情况等）日志内容，在实现阶段不断完善调试类日志内容。需要强调的是，好的调试类日志，绝不是一遍就可以写好的，因此团队要重视日志优化这件事情，不要让日志的质量持续降低（当项目变大时，项目的代码也存在一样的问题，越写越乱）。

• 在定位问题的过程中完善日志，如果定位问题花费了很长时间，那就说明日志还存在问题，需要进一步完善和优化；

• 需要思考是否可以通过优化日志，来提前预判该问题是否可能发生（如某种资源耗尽而导致的错误，可以对资源的使用情况进行记录）

• 定义好整个团队记录日志的规范，保证每个开发记录的日志格式统一；特别需要说明的是，对于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时，我们需要能知道以下信息：

1. 本软件系统/本软件组件输入输出是否正常；

2. 如果输出不正常，到底是输入异常导致 OR 软件系统或者组件处理出错导致；

3. 如果是系统或者组件内部出错，要能通过日志定位到具体原因。

4. 鉴于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[强制]: 系统版本号/各部件版本号/数据库版本号等相关版本信息需要以最高等级输出。