日志记录原则和方法

谁借莪１个温暖的怀抱￠ 2022-05-29 09:42 191阅读 0赞

在程序中打错误日志的主要目标是为更好地排查问题和解决问题提供重要线索和指导。但是在实际中打的错误日志内容和格式变化多样，错误提示上可能残缺不全、没有相关背景、不明其义，使得排查解决问题成为非常不方便或者耗时的操作。而实际上，如果编程的时候稍加用心，就会减少排查问题的很多无用功。 在阐述如何编写有效的错误日志之前， 了解错误是怎么产生的，  非常重要。

**错误是如何炼成的**

对于当前系统来说， 错误的产生由三个地方引入：

1.  上层系统引入的非法参数。 对于非法参数引入的错误， 可以通过参数校验和前置条件校验来截获错误；

2.  与下层系统交互产生的错误。 与下层交互产生的错误， 有两种：

a.  下层系统处理成功了，但是通信出错了， 这样会导致子系统之间的数据不一致；

对于这种情况， 可以采用超时补偿机制，预先将任务记录下来，通过定时任务在后续将数据订正过来。

更好的设计方案 ？

b.  通信成功了，但是下层处理出错了。

对于这种情况， 需要与下层开发人员沟通， 协调子系统之间的交互；

需要根据下层返回的错误码和错误描述做适当的处理或给予合理的提示信息。

无论哪一种情况， 都要假设下层系统可靠性一般， 做好出错的设计考虑。

3.  本层系统处理出错。

本层系统产生错误的原因：

**原因一： 疏忽导致。**疏忽是指程序员能力完全可避免此类错误但实际上没做到。比如将 && 敲成了 & ， == 敲成了 = ；  边界错误， 复合逻辑判断错误等。 疏忽要么是程序员注意力不够集中， 比如处于疲倦状态、加班通宵、边开会边写程序； 要么是急着实现功能，没有顾及程序的健壮性等。

改进措施：  使用代码静态分析工具，通过单元测试行覆盖可有效避免此类问题。

**        原因二： 错误与异常处理不够周全导致的。** 比如输入问题。 计算两个数相加， 不仅要考虑计算溢出问题， 还要考虑输入非法的情形。对于前者，可能通过了解、犯错或经验就可以避免， 而对于后者，则必须加以限定，以使之处于我们的智商能够控制的范围内，比如使用正则表达式过滤掉不合法的输入。对于正则表达式必须进行测试。对于不合法输入， 要给出尽可能详细、易懂、友好的提示信息、原因及建议方案。

改进措施：  尽可能周全地考虑各种错误情形和异常处理。在实现主流程之后，增加一个步骤：仔细推敲可能的各种错误和异常，返回合理错误码和错误描述。每个接口或模块都有效处理好自己的错误和异常，可有效避免因场景交互复杂导致的bug. 譬如，一个业务用例由场景A.B.C交互完成。实际执行A.B成功了，C失败了，这时B需要根据C返回合理的代码和消息进行回滚并返回给A合理的代码和消息，A根据B的返回进行回滚，并返回给客户端合理的代码和消息。这是一种分段回滚的机制，要求每个场景都必须考虑异常情况下的回滚。

**原因三： 逻辑耦合紧密导致。** 由于业务逻辑耦合紧密， 随着软件产品一步步发展， 各种逻辑关系错综复杂， 难以看到全局状况， 导致局部修改影响波及到全局范围，造成不可预知的问题。

改进措施：  编写短函数和短方法， 每个函数或方法最好不超过 50 行。 编写无状态函数和方法， 只读全局状态， 相同的前提条件总是会输出相同的结果， 不会依赖外部状态而变更自己的行为； 定义合理的结构、 接口和逻辑段， 使接口之间的交互尽可能正交、低耦合； 对于服务层， 尽可能提供简单、正交的接口； 持续重构， 保持应用模块化和松耦合， 理清逻辑依赖关系。对于有大量业务接口相互影响的情况， 必须整理各个业务接口的逻辑流程及相互依赖关系， 从整体上进行优化； 对于有大量状态的实体， 也需要梳理相关的业务接口， 整理状态之间的转换关系。

**       原因四： 算法不正确导致。**

改进措施： 首先将算法从应用中分离出来。 若算法有多种实现， 可以通过交叉校验的单元测试找出来， 比如排序操作； 如果算法具有可逆性质， 可以通过可逆校验的单元测试找出来， 比如加密解密操作。

**       原因五： 相同类型的参数，传入顺序错误导致。**比如，modifyFlow(int rx, int tx), 实际调用为 modifyFlow(tx,rx)

改进措施： 尽可能使类型具体化， 该用浮点数就用浮点数， 该用字符串就用字符串， 该用具体对象类型就用具体对象类型； 相同类型的参数尽可能错开； 如果上述都无法满足， 就必须通过接口测试来验证， 接口参数值务必是不同的。

**       原因六： 空指针异常。 **空指针异常通常是对象没有正确初始化， 或者使用对象之前没有对对象是否非空做检测。

改进措施： 对于配置对象， 检测其是否成功初始化； 对于普通对象， 获取到实体对象使用之前， 检测是否非空。

**       原因七： 网络通信错误。** 网络通信错误通常是因为网络延迟、阻塞或不通导致的错误。网络通信错误通常是小概率事件， 但小概率事件很可能会导致大面积的故障、 难以复现的BUG。

改进措施： 在前一个子系统的结束点和后一个子系统的入口点分别打 INFO 日志。 通过两者的时间差提供一点线索。

**       原因八： 事务与并发错误。 **事务与并发结合在一起， 很容易产生非常难以定位的错误。

改进措施：  对于程序中的并发操作， 涉及到共享变量及重要状态修改的， 要加 INFO 日志。更有效的做法？？？

**       原因九： 配置错误。**

改进措施： 在启动应用或启动相应配置时， 检测所有的配置项，  打印相应的INFO日志，  确保所有配置都加载成功。

**原因十： 业务不熟悉导致的错误。** 在中大型系统， 部分业务逻辑和业务交互都比较复杂， 整个的业务逻辑可能存在于多个开发同学的大脑里， 每个人的认识都不是完整的。这很容易导致业务编码错误。

改进措施： 通过多人讨论和沟通， 设计正确的业务用例， 根据业务用例来编写和实现业务逻辑； 最终的业务逻辑和业务用例必须完整存档； 在业务接口中注明该业务的前置条件、处理逻辑、后置校验和注意事项； 当业务变化时， 需要同步更新业务注释； 代码REVIEW。 业务注释是业务接口的重要文档， 对业务理解起着重要的缓存作用。

**原因十一： 设计问题导致的错误。**比如同步串行方式会有性能、响应慢的问题， 而并发异步方式可以解决性能、响应慢的问题， 但会带来安全、正确性的隐患。异步方式会导致编程模型的改变， 新增异步消息推送和接收等新的问题。使用缓存能够提高性能， 但是又会存在缓存更新的问题。

改进措施： 编写和仔细评审设计文档。 设计文档必须阐述背景、需求、所满足的业务目标、要达到的业务性能指标、可能的影响、设计总体思路、详细方案、预见该方案的优缺点及可能的影响； 通过测试和验收， 确保改设计方案确实满足业务目标和业务性能指标。

**原因十二： 未知细节问题导致的错误。** 比如缓冲区溢出、 SQL 注入攻击。 从功能上看是没有问题的， 但是从恶意使用上看， 是存在漏洞的。 再比如， 选择 jackson 库做 JSON 字符串解析， 默认情况下， 当对象新增字段时会导致解析出错。必须在对象上加 @JsonIgnoreProperties(ignoreUnknown = true) 注解才能正确应对变化。如果选用其他 JSON 库就不一定有这个问题。

改进措施：  一方面要通过经验积累， 另一方面， 考虑安全问题和例外情况， 选择成熟的经过严格测试的库。

**原因十三： 随时间变化而出现的bug。**有些解决方案在过去看来是很不错的，但在当前或者未来的情景中可能变得笨拙甚至不中用，也是常见的事情。比如像加密解密算法， 在过去可能认为是完善的， 在破解之后就要慎重使用了。

改进措施：  关注变化以及漏洞修复消息，及时修正过时的代码、库、行为。

**        原因十四： 硬件相关的错误。** 比如内存泄露， 存储空间不足，  OutOfMemoryError 等。

改进措施： 增加对应用系统的 CPU / 内存 / 网络等重要指标的性能监控。

系统出现的常见错误：

1.  实体在数据库中的记录不存在， 必须指明是哪个实体或实体标识；

2.  实体配置不正确， 必须指明是哪个配置有问题，正确的配置应该是什么；

3.  实体资源不满足条件， 必须指明当前资源是什么，资源要求是什么；

4.  实体操作前置条件不满足， 必须指明需要满足什么前置条件，当前的状态是什么；

5.  实体操作后置校验不满足， 必须指明需要满足什么后置校验， 当前的状态是什么；

6.  性能问题导致超时， 必须指明是什么导致的性能问题，后续如何优化；

7.  多个子系统交互通信出错导致之间的状态或数据不一致？

一般难以定位的错误会出现在比较底层的地方。 因为底层无法预知具体的业务场景， 给出的错误消息都是比较通用的。

这就要求在业务上层提供尽可能丰富的线索。错误的产生一定是多个系统或层次交互的过程中在某一层栈上不满足前置条件导致。 在编程时， 在每一层栈中尽可能确保所有必须的前置条件满足，尽可能避免错误的参数传递到底层， 尽可能地将错误截获在业务层。

大多数错误都是由多种原因组合产生。 但每一种错误必定有其原因。 在解决错误之后， 要深入分析错误是如何发生的， 如何避免这些错误再次发生。 努力就能成功， 但是：** 反思才能进步 ！**

** **

**如何编写更容易排查问题的错误日志**

打错误日志的基本原则：

1.  尽可能完整。 每一条错误日志都完整描述了： 什么场景下发生了什么错误， 什么原因（或者哪些可能原因）， 如何解决（或解决提示）；

2.  尽可能具体。 比如 NC 资源不足， 究竟具体指什么资源不足， 是否可以通过程序直接指明； 通用错误，比如 VM NOT EXIST ， 要指明在什么场景下发生的，可能便于后续统计的工作。

3.  尽可能直接。 最理想的错误日志应该让人在第一直觉下能够知道是什么原因导致，该怎么去解决，而不是还要通过若干步骤去查找真正的原因。

4.  将已有经验集成直接到系统中。 所有已经解决过的问题及经验都要尽可能以友好的方式集成到系统中，给新进人员更好的提示，而不是埋藏在其他地方。

5.  排版要整洁有序， 格式统一化规范化。 密密麻麻、随笔式的日志看着就揪心， 相当不友好， 也不便于排查问题。

6.  采用多个关键字唯一标识请求，突出显示关键字： 时间、实体标识（比如vmname）、操作名称。

排查问题的基本步骤：

登录到应用服务器 -> 打开日志文件 -> 定位到错误日志位置 -> 根据错误日志的线索的指导去排查、确认问题和解决问题。

其中：

1.  从登陆到打开日志文件： 由于应用服务器有多台， 要逐一登录上去查看实在不方便。 需要编写一个工具放在 AG 上直接在 AG 上查看所有服务器日志， 甚至直接筛选出所需要的错误日志。

2.  定位错误日志位置。 目前日志的排版密密麻麻，不易定位到错误日志。一般可以先采用"时间"来定位到错误日志的附近前面的地方， 然后使用 实体关键字 / 操作名称 组合来锁定错误日志地方。 根据 requestId 定位错误日志虽然比较符合传统，但是要先找到 requestId , 并且不具有描述性。最好能直接根据时间/内容关键字来定位错误日志位置。

3.  分析错误日志。 错误日志的内容最好能够更加直接明了， 能够明确指明与当前要排查的问题特征是吻合的， 并且给出重要线索。

通常， 程序错误日志的问题就是日志内容是针对当前代码情境才能理解，看上去简洁， 但总是写的不全， 半英文格式；一旦离开代码情境， 就很难知道究竟说的是什么， 非要让人思考一下或者去看看代码才能明白日志说的是什么含义。 这不是自己给自己罪受？

比如：

![复制代码][copycode.gif]

if ((storageType == StorageType.dfs1 || storageType == StorageType.dfs2) && (zone.hasStorageType(StorageType.io3) || zone.hasStorageType(StorageType.io4))) { // 进入dfs1 和dfs2 在io3 io4 存储。
    } else { log.info("zone storage type not support, zone: " + zone.getZoneId() + ", storageType: "
    + storageType.name()); throw new BizException(DeviceErrorCode.ZONE_STORAGE_TYPE_NOT_SUPPORT); }

![复制代码][copycode.gif]

zone 要支持什么 storage type 才是正确的?   Do Not Let Me Think !

错误日志应该做到： 即使离开代码情境，也能清晰地描述发生了什么。

此外，如果能够直接在错误日志中说明清楚原因， 在做巡检日志的时候也可以省些力气。

从某种意义上来说， 错误日志也可以是一种非常有益的文档，记录着各种不合法的运行用例。

目前程序 错误日志的内容可能 存在如下问题：

**1.  错误日志没有指明错误参数和内容：**

catch(Exception ex){ log.error("control ip insert failed", ex); return new ResultSet<AddControlIpResponse>( ControlIpErrorCode.ERROR_CONTROL_IP_INSERT_FAILURE); }

没有指明插入失败的 control ip. 如果加上 control ip 关键字， 更容易搜索和锁定错误。

类似的还有：

log.error("Get some errors when insert subnet and its IPs into database. Add subnet or IP failure.", e);

没有指明是哪个 subnet 的它下属的哪些 IP. 值得注意的是， 要指明这些要额外做一些事情， 可能会稍微影响性能。这时候需要权衡性能和可调试性。

解决方案： 使用 String.format("Some msg to ErrorObj: %s", errobj) 方法指明错误参数及内容。

这通常要求对 DO 对象编写可读的 toString 方法。

**2.  错误场景不明确：**

log.error("nc has exist, nc ip" + request.getIp());

在 createNc 中检测到 NC 已经存在报错。 但是日志上没有指明错误场景， 让人猜测，为什么会报NC已存在错误。

可以改为

log.error("nc has exist when want to create nc, please check nc parameters. Given nc ip: " + request.getIp());

log.error("\[create nc\] nc has exist, please check nc parameters. Given nc ip: " + request.getIp());

类似的还有：

log.error("not all vm destroyed, nc id " + request.getNcId());

改成 log.error("\[delete nc\] some vms \[%s\] in the nc are not destroyed. nc id: %s", vmNames, request.getNcId());

解决方案： 错误消息加上 when 字句， 或者错误消息前加上 【接口名】,  指明错误场景，直接从错误日志就知道明白了。

一般能够知道 executor 的可以加上 【接口名】， service 加上 when 字句。

**3.  内容不明确, 或不明其义：**

if(aliMonitorReporter == null) { log.error("aliMonitorReporter is null!"); } else { aliMonitorReporter.attach(new ThreadPoolMonitor(namePrefix, asynTaskThreadPool.getThreadPoolExecutor())); }

改为：log.error("aliMonitorReporter is null, probably not initialized properly, please check configuration in file xxx.");

类似的还有：

if (diskWbps == null && diskRbps == null && diskWiops == null    && diskRiops == null) { log.error("none of attribute is specified for modifying"); throw new BizException(DeviceErrorCode.NO_ATTRIBUTE_FOR_MODIFY); }

改为 log.error("\[modify disk attribute\] None of \[diskWbps,diskRbps,diskWiops,diskRiops\] is specified for disk id:" + diskId);

解决方案： 更清晰贴切地描述错误内容。

**4. 排查问题的引导内容不明确：**

** **

log.error("get gw group ip segment failed. zkPath: " + LockResource.getGwGroupIpSegmnetLockPath(request.getGwGroupId()));

zkPath ?  如何去排查这个问题？ 我该去找谁？ 到哪里去查找更具体的线索？

解决方案： 加上相应的背景知识和引导排查措施。

**5. 错误内容不够具体细致：**

** **

if (!ncResourceService.isNcResourceEnough(ncResourceDO, vmResourceCondition)) { log.error("disk space is not enough at vm's nc, nc id:" + vmDO.getNcId()); throw new BizException(ResourceErrorCode.ERROR_RESOURCE_NOT_ENOUGH); }

究竟是什么资源不够？ 目前剩余多少？ 现在需要多少？ 值得注意的是， 要指明这些要额外做一些事情， 可能会稍微影响性能。这时候需要权衡性能和可调试性。

解决方案：  通过改进程序或程序技巧， 尽可能揭示出具体的差异所在， 减少人工比对的操作。

**6. 半英文句式读起来不够清晰明白，需要思考来拼凑起完整的意思：**

log.warn("cache status conflict, device id "+deviceDO.getId()+" db status "+deviceDO.getStatus() +", nc status "+ status);

改为:

log.warn(String.format("\[query cache status\] device cache status conflicts between regiondb and nc, status of device '%s' in regiondb is %s , but is %s in nc.", deviceDO.getId(), deviceDO.getStatus(), status));

解决方案： 改为自然可读的英文句式。

总结起来， 错误日志格式可以为：

log.error("\[接口名或操作名\] \[Some Error Msg\] happens. \[params\] \[Probably Because\]. \[Probably need to do\].");

log.error(String.format("\[接口名或操作名\] \[Some Error Msg\] happens. \[%s\]. \[Probably Because\]. \[Probably need to do\].", params));

或

log.error("\[Some Error Msg\] happens to 错误参数或内容 when \[in some condition\]. \[Probably Because\]. \[Probably need to do\].");

log.error(String.format("\[Some Error Msg\] happens to %s when \[in some condition\]. \[Probably Because\]. \[Probably need to do\].", parameters));

\[Probably Reason\]. \[Probably need to do\]. 在某些情况下可以省略； 在一些重要接口和场景下最好能说明一下。

每一条错误日志都是独立的，尽可能完整、具体、直接说明何种场景下发生了什么错误，由什么原因导致，要采用什么措施或步骤。

问题：

1.  String.format 的性能会影响打日志吗？ 一般来说， 错误日志应该是比较少的， 使用 String.format 的频度并不会太高，不会对应用和日志造成影响。

2.  开发时间非常紧张时， 有时间去斟酌字句吗？ 建立一个标准化的内容格式，将内容往格式套，可以节省斟酌字句的时间。