你真的会打 Log 吗?

作者:祝欣鸿,任职Java工程师,负责新达达账户系统的研发工作,对工程规范、代码质量有深入理解。

工程师在日常开发工作中,更多的编码都是基于现有系统来进行版本迭代。在软件生命周期中,工程维护的比重也往往过半。当我们维护的系统出现问题时,第一时间想到的是查看日志来判断问题原因,这时候日志记录如果没有提供有效的信息,我们能做的只有深度 Code Review,耗时不说且效率低下。

日志

日志记录的好坏直接关系到系统出现问题时定位原因的速度。不少工程中都记录了挺多日志,但在实际问题排查中起到的作用却不大,开发人员还是需要打开 IDE 通过读代码来定位原因。那到底怎样的日志记录更合适呢?我们可以先思考一下这几个问题:

  1. 记录日志的目的?

  2. 什么是有效的日志?

  3. 记录日志的原则?

首先,日志需要用来记录用户操作、系统运行状态等信息,是一个系统的重要组成部分。然而由于日志并非系统核心功能,通常情况下并得不到开发人员的重视。在出现问题需要通过日志来定位时,才暴露中现有日志记录的很多不足。

其次,通过对日志的观察和分析,提前发现系统的潜在风险,避免线上事故的发生。

最终目标:线上系统出现问题时,通过日志就可以快速定位原因。

01

日志级别

在 slf4j 官网上可以看到官方对日志级别定义有8种之多:

这里介绍常用日志级别的同时顺带介绍一下不常见的日志级别 FATAL 和 TRACE。

FATAL - 表示需要立即被处理的系统级错误。当该错误发生时,服务已经出现了某种程度的不可用,系统管理员需要立刻处理。这是最严重的日志级别,因此该日志级别要慎用,如果这种级别的日志经常出现,那这日志也失去了意义。通常情况下,一个进程的生命周期中应该只记录一次FATAL级别的日志,即该进程遇到无法恢复的错误而退出时。

TRACE - 这个级别日志在开源框架中还挺常见,和DEBUG级别很像,主要作用是对系统每一步的运行状态进行精确的记录。通过它,可以查看某一个操作每一步的执行过程,精确定位是什么操作,有什么参数,执行顺序是怎样,最终导致了什么错误的发生。同时可以保证在不重现错误的情况下,通过分析 TRACE 级别的日志即可完成对问题的诊断。TRACE 和 DEBUG 用法相似,具体规范应该由团队自己定义,应该保证日志内容除了开发人员以外,运维、测试人员也可以通过 TRACE(或 DEBUG)日志来定位问题。

ERROR - 该级别的错误也需要马上被处理,但是紧急程度要低于FATAL。当ERROR错误发生时,已经影响了正常的业务功能。从这个意义上来说,实际上ERROR错误和FATAL错误对用户的影响是相当的。FATAL相当于整个服务已经挂了,而ERROR表示系统出现错误,但还能提供服务,只能不断地打印ERROR日志。特别需要注意的是,ERROR应当属于服务自己的异常,是需要马上得到人工介入并处理的,如果出现了ERROR日志业务上又不需要处理的就不应该记为ERROR级别,这一点是区别于INFO的明显标识。例如由于用户自己操作不当,传入非法请求参数时,是绝对不应该记为ERROR级别;还有业务处理结果为失败的情况,比如扣款操作遇到用户余额不足,也不能记为ERROR。

INFO - 该种日志记录系统处理业务的概要信息,例如一个业务请求的入参和执行结果以及耗时等等。通过查看INFO级别的日志,可以很快地对系统中业务情况有个基本了解,有哪些业务处理成功哪些又失败了。INFO日志不宜过多,太多的话造成信息干扰不利于查问题;

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

Rule 1:     整个团队(包括运维)对日志级别有明确规范。

Rule 2:     绝不打印没有用的日志,防止无用日志淹没重要信息。

02

日志维护

通过系统出现的问题来优化日志,是一项长期的实践,不断地从日志发现系统的问题,不断地从系统错误发现日志的问题。

  1. 定义好整个团队记录INFO、DEBUG(或TRACE)日志规范,保证每个开发记录的日志格式统一;

  2. 整个团队(包括开发,运维和测试)定期对记录的日志内容进行Review;

  3. 通过查问题的过程来不断优化日志记录;

  4. 运维或测试在日志中发现的问题,需要及时向开发人员反映;

在线上出现问题的时候,需要尽快发现问题并解决;同时,需要借此机会好好思考一下当前系统的日志是否合理,应该考虑以下问题:

  1. 如果定位问题花费了很长时间,那就说明系统日志还存在问题,需要进一步完善和优化。

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

通过系统出现的问题来优化日志,是一项长期实践,需要不断从日志中发现系统的问题,同时也需要不断从系统异常中发现日志的问题。

Rule 3:     定期对日志内容进行优化更新。

03

日志格式

日志格式一定要统一,不能任由开发人员的喜好来。系统中日志格式不统一,不利于自动化处理。不要出现个性化的日志,否则可能只有开发人员自己才能看懂。比如 logback 中 pattern 的格式,以及日志的切分轮转策略,团队内应该有统一的标准。 

这么做的好处很明显:团队内任何一个人甚至团队以外的人看到这段错误日志时,都能根据记录的有效信息来帮助快速定位问题。

Rule 4:     把日志的格式、大小,切分轮转策略等作为规范建立起

来。

实践

这里介绍一下账户团队在工程维护中对日志实践的一些经验。

原先日志文件有3个:info.log, error.log, sql.log,日志按天轮转保留 3 天,info、error 记录混乱没有明显区别。这里来几个教科书级别的错误示范,贴几段遗留 INFO 级别日志。

  • 大量 "Going to buffer response body" 无效日志信息,这里只展示了一部分。

  • 异常堆栈信息绝不应该出现在 INFO 级别日志中。

  • 异常中一串数字 “14999467266450” 是个啥,根本看不懂,只能去看代码。

  • 有堆栈信息却没有原始请求参数,排错无从下手。

  • 后面定位到确实是转账金额小于零,但传入非法参数绝不应该记录为ERROR,更不应该打印堆栈信息,因为这不表示服务本身有问题。

  • 没有原始请求参数和响应返回。

  • 日志记录区分不开是由几个请求产生。

看完这些,手中 40 米的大刀已经饥渴难耐。

线上出现问题时,光是寻找日志中的“蛛丝马迹”就花去不少时间,还是得靠 Code Review 来解决。开发环境联调,系统之间 rpc 调用没有日志记录,出了问题也不知道哪个环节出错。

针对上面这些情况,是时候做一些改变了,经过团队商议,对日志做了一些改造,重点解决2个问题:

  1. 系统间相互调用的入参出参必须记录。

  2. 能快速找到由一个请求产生的所有日志。

01

日志分类

info.log:业务关键步骤信息。

error.log:业务发生的错误以及堆栈信息。

sql_info.log:超过10ms的SQL调用。

api_info.log:api调用的关键信息。

rpc_info.log:rpc调用的信息。

这里说下 api_info.log、rpc_info.log,这会是分布式系统中相互调用的关键凭证,里面记录了这些信息:

  • 请求参数

  • traceId,日志追踪使用的唯一ID

  • 请求客户端IP(rpc日志中记录目标服务端IP端口)

  • 响应参数

  • 处理耗时

和运维团队沟通后,统一了 logback pattern 配置:

张同学:这里说的 traceId 是个啥?

traceId 的作用是把分散在各个日志文件中的日志信息都串起来,即一个请求产生的所有日志都有同一个唯一的 traceId,这样在ELK中查询日志时,把 traceId 作为查询条件一步就把这次请求的所有日志都查出来。同时 traceId 作为响应参数之一,便于系统间排查问题。

李同学:traceId 需要侵入线程上下文,在不对业务代码做修改的情况下,有办法实现吗?

当然是有的,在 Controller 的 AOP 中使用 slf4j MDC 把 traceId 放到线程上下文,对业务编码无入侵。traceId 的生成策略,可以有很多选择,只要在当天的日志索引中唯一即可,并没有太强的要求,账户团队最后使用的是毫秒时间戳 + 幂等ID + 6位随机数。

有了 traceId 之后,通过日志定位问题就只有2步:

  1. 根据业务关键字信息查询 api.log,找到原始的入参和返回值。

  2. 如果返回参数不够清楚,根据其中 traceId 可以把所有日志都查出来,能清楚看到关键步骤、 rpc 调用和异常 error 信息。

监控、报警

最后介绍一下达达运维团队提供基于日志监控的实时报警系统。

上面提到对于 ERROR 级别的日志,需要立即介入处理,所以这是日志中的重点监控对象。这套架构中 Filebeat 负责把日志实时采集到监控系统中用以分析,监控系统同时提供多种灵活的报警策略,支持邮件、短信、电话等多种报警形式。

监控报警的场景不仅限于ERROR级别,我们通过监控 INFO 级别日志可以发现一些系统的潜在风险,比如中间件或者 rpc 调用时长超过 100ms,在1分钟内出现超过 20 次,需要报警提醒。我们可以根据业务特点,和运维一块设定灵活的报警策略。

总结

为了实现仅通过日志信息就能定位问题的最终目标,更为了有效提高工程质量,我们最后再回顾一下日志记录的几个标准操作。

  1. 团队(包括运维)对日志级别有明确规范。

  2. 绝不打印没有用的日志。

  3. 定期对日志内容进行优化更新。

  4. 日志格式、大小,切分轮转策略需要形成规范

我来评几句
登录后评论

已发表评论数()

相关站点

+订阅
热门文章