你真的会打 Log 吗？

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

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

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

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

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

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

在 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级别的日志，就尽量不要打；

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

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

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

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

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

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

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

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

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

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

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

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

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

和运维团队沟通后，统一了 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 次，需要报警提醒。我们可以根据业务特点，和运维一块设定灵活的报警策略。

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