日志最佳实践

近一年多以来想要分享知识的欲望降低了许多，不知道是否是近一年来工作较忙的原因，导致整个21年没有对外输出什么内容，唯一的一篇 “Log4j2 Jndi 漏洞原理解析、复盘” 还是在趁热想抓波热点的情况下写的这篇文章（21年12月10号爆出漏洞、11号公司内修复、12号凌晨05:00趁热发布文章，发布完以后直接埋头睡了一天，现在想来简直丧心病狂！）。

转眼已经到了2022，复盘2021的时候会发现并非如此，整个2021年是有做很多输入的，但由于并没有对外输出，而只是将对应的内容简单的记录到了自己的笔记中，导致回头再看时，会发现笔记中的很多内容并不系统，只是记录了一个点的问题，而非面。

输出是一个很好的习惯，输入并输出的过程也是在不断的翻新自我知识体系的过程，在持续输出的过程中，不仅帮助了自己也可能会帮助到他人。一举多得。

所以，就用这篇来作为2022年博客园的第一篇吧，GO，GO！ （PS：该篇文章已经在笔记中躺了有段时间了、略微整理后，重新分享出来。）

背景

公司当前日志平台一天所沉淀的业务日志有近600亿条，40T左右的大小，随着公司内降本增效的事项推进，再加上业务方业务日志越来越多等问题，导致整个日志平台的资源是越发紧张的。

为了约束业务团队的日志数量，除了一些硬性的手段（日志SDK端采样、服务端采样、成本平摊），以及通过一些硬性的指标，要求业务团队的日志条数链路比、日志大小链路比 必须控制在一个合理的范围内之外，还需要一些小的科普。

而这个科普便是这次内容的主题 “日志最佳实践”，目的是为了让部分研发知晓：“噢，日志原来也是要像代码一样不断优化的啊”。

前言

日志用来记录用户操作、系统运行状态等，是一个系统的重要组成部分。然而，由于日志通常不属于系统的核心功能，所以常常不被团队成员所重视，在出现问题需要通过日志来定位时，才发现日志还存在很多问题；日志记录的好坏直接关系到系统出现问题时定位的速度，同时通过对日志的监控和分析，可以提前发现系统可能的风险，避免线上事故的发生。

现阶段我们的监控系统已经为我们的服务稳定性提供了较强的支撑，其中实时的异常大盘、日志的异常告警、日志的统一收集检索以及日志和链路的串联等功能为我们在微服务体系下问题的诊断提供了快速的排查方案。但随着时间的推移，代码中的日志质量持续降低（当项目变大时，项目的代码也存在一样的问题，越写越乱）。随着越来越多不规范的日志开始出现，除了会增加监控系统的承压，还会对线上的问题定位、稳定性监控等造成干扰。所以，日志的优化则势在必行，一方面监控系统降压降本，另一方面增加线上服务的稳定性及故障快速定位的能力。

原创声明：作者：陈咬金、 博客地址：https://www.cnblogs.com/zh94/

日志的分类

日志从功能来说，可分为诊断日志、统计日志、审计日志。
诊断日志， 典型的有：

  • 请求入口和出口
  • 外部服务调用和返回
  • 资源消耗操作: 如读写文件等
  • 容错行为：如云硬盘的副本修复操作
  • 程序异常： 如数据库无法连接
  • 后台操作：定期执行删除的线程启动、关闭、配置加载

统计日志：

  • 用户访问统计：用户IP、上传下载的数据量，请求耗时等。（常用的Log Metric 则是统计日志）

审计日志：

  • 管理操作、系统安全事件、非法访问记录等

需要避免的日志记录方式

在写代码的过程中，统计和审计日志是带有强烈目的性、功能性的，比如：用户访问统计的图表，非法访问的记录等。

但是针对诊断日志则不然，由于我们无法确定系统在具体哪行代码中会出现异常，所以诊断日志的添加也就因人而异，不同研发的风格，喜欢在不同的代码处增加诊断日志。

比如：有些研发同学喜欢在方法的入口处增加日志，有些研发则是在可能会出现不确定性的判断体中增加日志。这些都没问题，毕竟某块代码哪里最容易出现问题，最需要诊断日志，这些只有具体的研发才知晓。

但是我们需要约束并避免的情况是：

1、日志中不要记录无用的信息

如下图中的服务日志：单条日志的长度已经超出了5000的长度，并已经触发了服务端的日志截断操作。（既然是诊断日志，应该是诊断该方法内的部分属性，或者可能出现问题的属性，而不应该是全部输出）

2、不要记录无用的日志（不利于问题分析诊断的日志）

如下图中：日志Msg为 “threadLocal进行清除”这段日志，如果说这段日志有没有意义？“有的”，这段日志表示 threadLocal被清除了，很直接明了。但是如果说这段日志对问题的分析诊断有没有作用？作用极小。

假设这里 ThreadLocal remove() 的操作执行前是有 If 判断，判断为 true 时，则执行ThreadLocal 清除，那么对应的日志应该是添加到 else 代码块中，如果判断条件为 false，则 else 代码中输出 WARN 日志，或者 ERROR 日志，表示此处存在风险或者异常需要进行关注，而不是在此处增加 INFO 日志，告知对应的研发或者测试同学 “ThreadLocal 清除成功了”。

ThreadLocal remove() 这个代码块被执行，是一个必然为真的操作，如果存在对应清除失败的情况，应该最终是会体现在对应的异常当中。所以针对这样一个必然为真的代码一定要增加对应的日志，那么最好的方式是调整日志级别为DEBUG。

3、能够放在一条日志中的信息，尽量放在一条日志当中，而不要放在多条日志中进行输出。

4、日志内容中不能包含敏感性信息

原创声明：作者：陈咬金、 博客地址：https://www.cnblogs.com/zh94/

日志的持续优化

理想中的日志应该是不多不少的状态，太多的信息则是噪音，太少的信息又不够充分，我们需要在实际的运维过程中，结合线上问题的定位，不断地进行优化。最关键的一点是，团队要重视日志优化这件事情，不要让日志的质量持续降低。

此处推荐如下几个较好的实践：

  • 在定位问题的过程中完善日志，如果定位问题花费了很长时间，那就说明系统日志还存在问题，需要进一步完善和优化；
  • 需要思考是否可以通过优化日志，来提前预判该问题是否可能发生（如某种资源耗尽而导致的错误，可以对资源的使用情况进行记录）
  • 定义好整个团队记录日志的规范，保证每个开发记录的日志格式统一；特别需要说明的是，对于DEBUG/TRACE级别的日志，也需要定义好清晰的格式，而不是由研发人员自由发挥；
  • 整个团队（包括开发，运维和测试）定期对记录的日志内容进行Review；
  • 开发做运维、测试，通过在查问题的过程来优化日志记录的方式；
  • 测试在日志中发现的问题，都需要及时向开发人员反映；

1、输出日志时要考虑日志的使用者，例如如果日志需要由系统的测试人员来看，那就不能输出：

2022-03-01 14:08:16.244 WARN [http-nio-20959-exec-86] com.ymm.ability.IdentifyValidateAbility ErrorCode:1426

至少应该是：

2022-03-01 14:08:16.244 WARN [http-nio-20959-exec-86] com.ymm.ability.IdentifyValidateAbility ErrorCode:1426, Message: callback request (to http://example.com/callback) failed due to socket timeout

这样测试人员一眼就能清楚问题的原因，而不需要再通过开发来查看ErrorCode对应的具体错误。

2、日志的记录信息要完整，尤其是针对异常的日志而言，如：

  • 在持久化数据修改时记录修改前和修改后的值。
  • 记录关键参数，出错时的关键原因等。
  • 记录对应的异常代码执行前的上下文信息。

关于日志级别

  • FATAL — 表示需要立即被处理的系统级错误。当该错误发生时，表示服务已经出现了某种程度的不可用，系统管理员需要立即介入。这属于最严重的日志级别，因此该日志级别必须慎用，如果这种级别的日志经常出现，则该日志也失去了意义。通常情况下，一个进程的生命周期中应该只记录一次FATAL级别的日志，即该进程遇到无法恢复的错误而退出时。当然，如果某个系统的子系统遇到了不可恢复的错误，那该子系统的调用方也可以记入FATAL级别日志，以便通过日志报警提醒系统管理员修复；

  • ERROR — 该级别的错误也需要马上被处理，但是紧急程度要低于FATAL级别。当ERROR错误发生时，已经影响了用户的正常访问。从该意义上来说，实际上ERROR错误和FATAL错误对用户的影响是相当的。FATAL相当于服务已经挂了，而ERROR相当于好死不如赖活着，然而活着却无法提供正常的服务，只能不断地打印ERROR日志。特别需要注意的是，ERROR和FATAL都属于服务器自己的异常，是需要马上得到人工介入并处理的。而对于用户自己操作不当，如请求参数错误等等，是绝对不应该记为ERROR日志的；

  • WARN — 该日志表示系统可能出现问题，也可能没有，这种情况如网络的波动等。对于那些目前还不是错误，然而不及时处理也会变为错误的情况，也可以记为WARN日志，例如一个存储系统的磁盘使用量超过阀值，或者系统中某个用户的存储配额快用完等等。对于WARN级别的日志，虽然不需要系统管理员马上处理，也是需要及时查看并处理的。因此此种级别的日志也不应太多，能不打WARN级别的日志，就尽量不要打；

  • INFO — 该种日志记录系统的正常运行状态，例如某个子系统的初始化，某个请求的成功执行等等。通过查看INFO级别的日志，可以相对较快的对系统中出现的 WARN,ERROR,FATAL错误进行定位。INFO日志不宜过多，通常情况下，INFO级别的日志应该不大于TRACE日志的10%；

  • DEBUG OR TRACE — 这两种日志具体的规范应该由团队自己定义，该级别日志的主要作用是对系统每一步的运行状态进行精确的记录。通过该种日志，可以查看某一个操作每一步的执 行过程，可以准确定位是何种操作，何种参数，何种顺序导致了某种错误的发生。可以保证在不重现错误的情况下，也可以通过DEBUG（或TRACE）级别的日志对问题进行诊断。需要注意的是，DEBUG日志也需要规范日志格式，应该保证除了记录日志的开发人员自己外，其他的如运维，测试人员等也可以通过 DEBUG（或TRACE）日志来定位问题；

原创声明：作者：陈咬金、 博客地址：https://www.cnblogs.com/zh94/

INFO和DEBUG

了解了上述日志级别的含义后，可能仍然会存在的一个问题是，INFO和DEBUG到底如何区分？我觉得这个日志既可以是INFO也可以是DEBUG？如何处理？

此处简单给出一些参考：

对于业务系统来说，INFO 日志应该看起来像一本书。它应该告诉你发生了什么，而不一定是如何发生的，比如：

INFO  | 发送用户注册邮件通知。[user="Thomas", email="thomas@tuhrig.de"]
INFO  | 邮件发送给用户 [user="Thomas"]
INFO  | 发送用户取消关注邮件通知。[user="Thomas", email="thomas@tuhrig.de"]

而对于系统当中的技术细节，则通常更应该使用DEBUG日志，DEBUG 日志可以更详细地了解该过程的工作方式

DEBUG | 将用户信息发送进MQ通知列表。[user="Thomas", email="thomas@tuhrig.de"]
INFO  | 发送用户注册通知 [user="Thomas", email="thomas@tuhrig.de"]
DEBUG | 开始发送当天邮件通知的定时任务。 [subscribers=24332]
INFO  | 邮件发送给用户 [user="Thomas"]
INFO  | 发送用户取消关注邮件通知。 [user="Thomas", email="thomas@tuhrig.de"]

想象一下，你在浏览INFO日志的时候，是在查看该系统的运行状态，此时看INFO日志更关注的是系统的运行指标，而并非那些技术上的细节是否执行成功。对应的技术细节是否执行成功应该是体现在对应的DEBUG日志当中，通过浏览DEBUG日志以此来对系统的运行进行精确的记录和诊断。

所以，类似于上面最初所提到的“ threadLocal 清除成功”这种日志，如果有必须存在的意义，则应该是添加到DEBUG级别当中更为合适。

而对于技术类系统来说，比如中间件，工具类，公共服务等来说，INFO级别的日志同样应该是告诉你发生了什么，而不是对应的技术细节。

比如：

  1. 远程加载了对应的配置文件，那么此时 INFO 输出该配置文件的内容则没有问题。
  2. JVM启动成功后，会有一个INFO级别的 Started Application in 35.499 seconds (JVM running for 45.536) 来表示JVM启动成功，但JVM是不会把类的加载过程 INFO 输出出来，因为对于INFO日志来说，并不关注这个。
  3. MVC的服务在服务启动后，同样会使用INFO级别的日志，将加载成功的Controller接口输出出来，而并不会通过INFO来告知使用方Controller的加载细节。
2022-03-01 15:18:03,553 INFO  [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] [main] Mapped "{[/nondestructive/release/health/check],methods=[POST],consumes=[application/json;charset=UTF-8],produces=[application/json;charset=UTF-8]}"

所以基于上述的一些内容，我们可以得到一些共性的认知，INFO级别的日志更应该关注的是系统中发生了什么较为重要的事件，需要让日志的查看者关注到这些信息。而不是技术的执行细节上执行了那些流程。执行细节应该是由DEBUG日志来进行输出。

所以对于在线下DEV和QA环境进行日志诊断、问题排查时，应该更多的是查看DEBUG日志来进行问题的排查，而不应该过多的依赖 INFO 日志。

对于线上环境则应该屏蔽掉DEBUG日志的输出，仅需要观察INFO，WARN，ERROR日志，来观察服务的运行状态。

在项目中日志优化应该是比代码、架构优化更为频繁的操作，我们应该随着问题的排查来不断的优化我们的日志输出。

同时，从日志的功能分类上我们也可以得知，日志的最重要的一个特性是：诊断日志，我们在不断优化日志的同时，也是对自己项目深入诊断的过程，在优化诊断日志的过程中，如果可以提前预判到某些问题的发生，如：连接池的耗尽，对象等资源的加载统计，而提前增加了诊断日志。这将会对于我们后续故障时的问题定位有着非常好的参考作用。

参考资料

Log4j2 Articles and Tutorials
Logging best practices to get the most out of application level logging
The Art of Test Driven Development: Understanding Logging
中小企业运维需要重视日志分析
王健：最佳日志实践

posted @ 2022-04-07 19:52  陈咬金  阅读(1291)  评论(2)  编辑  收藏  举报