日志打印的碎碎念总结 - bmilk

众所周知，日子作为最强的甩锅神器，合理合适的记录日志就是一个问题。今天我想总结下我对日志的看法

1、有意义的日志信息——为日志消息添加上下文

写这一行日志的时候思考下，生产出现异常的时候，这一行日志是否能提供有效的帮助去解决问题

这是最重要，也是最难做到的一个总结。在处理问题的时候，尤其是难以复现的问题，能协助处理问题的就只有日志文件，开发人员必须能从中了解到当时发生了什么！

当开发人员看到日志时，通常会根据日志推断问题发生时的上下文消息，不幸的时候日志本身并没有这个上下文，因此需要开发者手动将这些信息补充到日志中，如果不能也可加入操作的目的或者结果，便于理解。

比如ERROR: save error - SQL Excepetion这条日志，当你排查问题的时候价值几乎为0，除了知道时SQL执行出错外，没有任何信息。更好，更有用的信息应该是这样ERROR: save error, data com.xxx.Cat(name = name, age=1) - SQL Excepetion,其中解释了Cat是一个类，并且记录了对应示例的相关内容，注意是相关内容，而不是全部，无用的信息应该被去除，避免一些无用信息混淆日志文件。

2、尽可能使用英文记录日志

英文可能没有中文读起来方便，但是英文依然是记录日志最好的语言，没有之一，原因如下：

• 无法预知日志消息的内容以及他将被归档在何地，以何种方式被打开。英文将以ASCII字符被记录，如果日志消息使用特殊字符集乃至UTF-8，当被阅读者打开的时候都有可能无法正确呈现。并且还可能存在用户的输入采用不同的字符集或者编码的问题
• 国际化。如果不确定程序的使用者是谁，那么英文会是最好的选择。

3、选择合适的记录工具

犹记得在我刚开始写代码的时候，为了记录日志信息使用了System.out.println()，尽管这个解决了问题，但是这是一个非常愚蠢的方式。缺点数不胜数。
尽管java生态种提供了诸如Log4j、JCL、slf4j 和 logback等诸多第三方日志框架，但请尽量使用slf4j的门面模式来记录，有利于维护和各个类的日志处理方式统一，并且可以在保证不修改代码的情况下，很方便的实现底层日志框架的更换。

4、不要写的太多但更不能太少

这句话听起来似乎很矛盾，但我们确实应该平衡日志的数量。试想在凌晨3点，你要在漫天日志中寻找问题的根源，如果被大量日志混乱你的思路这并不是一件好事。但如果日志太少，找不到问题根源，这更是一个问题。

到底多少合适，没有一个准确的数字，有一个解决思路是，前期可以多打日志，功能上线后，对日志进行分析，并根据问题的减少而减少日志，或者补上缺失的日志

5、在合适的地方记录日志

看这个标题，如果问我什么是合适的地方，我也不知道，但是如果从日志的用出来看，那将会有一些答案

• 远程调用或者第三方API开始与结束：众所周知，日志可以作为一个甩锅利器，当对方告诉你他做了什么而你认为没有或者不对的时候,日志就是最有力的证据
• 系统API开始与结束：这块就是自己系统的大门，谁来都得留下影子，别人说没给的时候，这里同样也是证据。另外在日志排错、性能分析、链路追踪方面很有帮助
• 异常块：所有捕获的异常军应该记录异常内容
• 应用的启动、停止日志
• 其他日志：可以根据业务需要，记录相应的日志，比如某些SQL查询的结果

6、在合适的环境使用合适的日志等级

java生态种可以使用的日志框架都有日志级别的概念，常见的日志级别如下：

• DEBUG：主要输出调试性质的内容，该级别的日志主要用于在开发、测试阶段输出，该级别的日志应尽可能的详细，比如各类调试信息、输入输出信息等等。
• INFO：业务系统记录日志的关键信息。开发可以将初始化系统配置，业务状态变化信息、流程核心记录到这个几倍种，方便运维工作及错误回溯时上下问场景复现
• WARN：主要输出警告性质的内容，该内容是可以预知，并且有规划的，比如乐观锁更新失败、方法空参等等
• ERROR：主要针对一些不可预知的、对应用影响打的错误、异常信息。比如catch代码块抓取的数据通信异常、文件异常。在输出ERROR级别的日志时，尽量的多输入方法参数，方法过程中产生的对象、错误、异常对象数据。

不同的环境应当使用不同日志级别，这样可以过滤掉级别过低的消息我通常使用的配置如下：
-生产：自己编写的代码的Info级别和第三方库的warn级别
-开发、测试：自己编写的代码的debug级别和第三方库的warn级别

7、在提交之前删除仅仅提供帮助功能的日志代码

在开发、测试期间，通常会打印很多的日志来记录应用过程中发生了什么，比如：

public void method(String str){
    log.info("method start, str{}", str);
    if("NO".equals(str)){
        log.debug("the param is no");
        // do other
    }
}

这些日志的主要目的是通过显示的调用及内部的方法数值来跟踪程序的行为，但是当这些代码发布后，log.debug("the param is no");将没有什么意义。所以在开发完成后，在代码合并到发版分支之前应当删除不必要的日志信息

8、了解日志框架的核心选取合适的日志字符串构造方式

选取不合适日志字符串构造方式可能会导致额外的开销，比如下面的两行代码

log.debug(String.formt("name=%s, age=%s", "test", 1));
log.debug("name={}, age={}", "test", 1);

这两行代码的最后日志输出都是：

name=test, age=1

但是当日志输出级别为INFO的时候却有巨大的时效差距。

• 当使用第一种方式构造日志对象时，会先生成字符串name=test, age=1， 并传参给log.debug()函数，之后判断出日志输出级别为INFO，不再输出日志。
• 使用第二种方式的时候，会先判断是INFO级别的日志输出，从而减少了构造字符串的时间。

关于SLF4J的构造方式可以参考https://www.slf4j.org/faq.html#logging_performance

9、 程序可以理解的日志

我对日志的要求第一要义是解决生产问题，所以一定是要人能读懂的日志。但有时对于大量的日志，我们需要自动化脚本进行批处理，那么我们就需要程序能够理解。

假设有这样一行语句

log.info("User {} plays {} in game {}", userId, card, gameId);

他将产生这样的文本

2013-01-12 17:49:37,656 [T1] INFO  c.d.g.UserRequest  User 1334563 plays 4 of spades in game 23425656

如果想要进行解析，正则表达式可能会是这样(没有验证)/User (d+) plays (.+?) in game (d+)$/
这样很容易出错，玩意用户就叫play怎么办呢？

我们可以将语句改成这样

log.info("User [{}] plays [{}] in game [{}]", userId, card, gameId);

所有的参数值都放在[]之间，这样就能更好的让程序分析代码

10、符合法律法规

基于各国、各行业的法律法规，不要打印用户的敏感信息，例如：银行卡号、身份证号、手机号

参考文档：
[1] The 5 Java logging rules
[2] Logging Best Practices: The 13 You Should Know
[3] logging_performance
[4] 日志粒度总结