Java日志通关（五） - 最佳实践

一、总是使用接口层

无论是写代码还是实现一个三方工具，请只使用接口层记录日志。

如果需要向外提供三方工具，记得在依赖中将日志的实现层及适配层标记为 optional，比如：

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-core</artifactId>
  <version>${logback.version}</version>
  <scope>runtime</scope>
  <optional>true</optional>
</dependency>

简单解释一下：

• <scope>runtime</scope>：runtime 的包编译时会被忽略（认为运行环境已经有对应包了）；
• <optional>true</optional>：依赖不会传递，Maven 不会自动安装此包；

二、不要打印分隔线

不要打印类似这种只包含分隔线的内容：log.info("========== start ==========")，因为在茫茫的日志中，这句日志的下一条很可能来自其他异步任务，如果使用 SLS 收集甚至来自另一台机器，这条分隔线根本起不到任何作用。

正确的方式是通过关键字进行标记，比如：log.info("FooBarProcessor start, request={}", request)，之后就可以通过关键字 FooBarProcessor 快速过滤，这对于 grep 和 SLS 都适用。

另外，可以用 Marker 让日志语义更清晰（可以参考第三篇中【四、Marker】节），只是麻烦了点儿，看个人喜好。

三、避免因写日志而抛错

比如没有判空就直接调用了它的方法：

Object result = rpcResource.call();

// 如果 result 为 null 会抛 NPE
log.info("result.userId={}", result.getUserId());

这个问题老生常谈，这里不展开说了。

四、两个 Fastjson 参数

4.1 IgnoreErrorGetter

Fastjson 的序列化其实是依赖于类中的各个 getter，如果某个 getter 抛异常则会阻断整个序列化。但其实有些 getter 异常并非严重问题，此时就可以使用 SerializerFeature.IgnoreErrorGetter 参数忽略 getter 中抛出的异常：

public class Foo {
    private Long userId;
    @Deprecated
    private Long accountId;

    // getter 有异常抛出
    public Long getAccountId() {
        throw new RuntimeException("请使用 userId");
    }
}

// 这样打印日志，就不会被 getter 抛出的异常阻断了
log.info("foo={}", JSON.toJSONString(foo, SerializerFeature.IgnoreErrorGetter));

4.2 IgnoreNonFieldGetter

比如有个 Result包装类如下（注意 isError 方法），当被 Fastjson 序列化时，会输出 "error":false。如果希望忽略掉类似这种没有实体字段对应的 getter 方法，就可以追加 SerializerFeature.IgnoreNonFieldGetter 参数：

@Data
public class Result<T> {
    private boolean success;
    private T data;

    public boolean isError() {
        return !success;
    }
}

// 这样打印日志，就不会有 "error":false 了
log.info("result={}", JSON.toJSONString(result, SerializerFeature.IgnoreNonFieldGetter));

这个参数对于打印 Result 包装类非常有帮助。如果打印出 "error":false，那当你希望使用 error 关键字查询错误时，就会匹配到很多包含 error 却并非错误的无效数据。

五、不要遗漏异常堆栈

我们在第三篇【3.1 info方法】节中提到，异常值参数是不占用字符模板的，如果你的参数数量不匹配，很可能打印结果与预期不符。如果你这样写：

Exception e = new RuntimeException("blahblahblah");
log.error("exception={}", e); // 此时 IDEA 会给出警告：参数比占位符少

此时因为 e 与对应的{}位置匹配，Slf4j 会尝试将异常转为字符串拼到日志模板中，最终这句相当于：

log.error("exception={}", e.toString());

最终你只能得到 exception=blahblahblah，而堆栈就丢掉了。正确的做法是要保证异常参数不占用字符模板：

// 用 e.getMessage() 拼到日志信息后，同时有独立的 e 用于打印堆栈
log.error("exception={}", e.getMessage(), e);

最终会输出：

exception=blahblahblah
换行后会有堆栈信息

六、限制日志输出长度

6.1 限制日志文本最大长度

有时候一个 POJO 非常大，当我们通过 ：

log.info("result={}", JSON.toJSONString(result))

打印日志时，整条日志就会变得很长。不但对性能会有影响，主要这么大的结果对实际问题排查也不见得有帮助。可以参考第四篇【3.2 Format modifiers】来限制消息最大长度，并将超出的部分丢弃：

%.-2000message

6.2 限制堆栈的层级

其实 Logback 天然支持，比如 %exception{50} 就可以只打印 50 层。同时 Logback 针对异常堆栈有更多的控制能力，可以参考官方文档 Evaluators[1]。

七、将堆栈合并为一行

有些同学希望将堆栈在一行输出，保证通过管道（|）进行多层 grep 时捞到期望的记录。其实通过 Logback 配置就可以支持这个能力，主要用到我们在 【4.3.1 Conversion Word】中提过的 %replace：

%replace(%exception){'[\r\n\t]+', '    '}%nopex

简单说明一下：

• %replace(p){r, t}：将给到的 p，使用正则 r 进行匹配，命中的替换为 t，所以上边就是，将 %exception 中的 [\r\n\t]（即换行、回车、Tab）替换为    （四个空格）；
  
• %nopex：如果不加，Logback 会自动在日志最后追加 %exception，导致异常堆栈打两遍（一遍我们自己转为一行的，一遍带原始换行的）；
  

甚至，如果你对异常堆栈的长度有要求，参考第四篇【3.2 Format modifiers】和【六、限制日志输出长度】两节中的知识，我们还可以这样：

%.-10000replace(%exception{50}){'[\r\n\t]+', '    '}%nopex

即：

• 只打印前 50 层堆栈；
  
• 转为一行后，再限制最大长度为 10000，超过的部分丢弃尾部字符；

八、不建议使用 %method 和 %line

在 Logback 的配置中，可以通过 %method 和 %line 输出方法名和行号。但这两项依赖于当前的堆栈轨迹 (StackTrace) ，而获取堆栈轨迹的代价比较高，日志一多就会占用大量的 CPU，所以一般情况不建议在日志中输出这些字段。如果对方法名有输出要求，可以直接硬编码到输出字符串中，比如：

log.info("queryUserInfo, request={}, result={}", request, result);

九、不要将日志输出至 Console

我们平时调用 System.out.println 时，默认输出位置就是控制台。Logback 也提供了 ch.qos.logback.core.ConsoleAppender 用于将日志输出至控制台。但：

• 机器上线后，没有人会盯着控制台看，所以输出至控制台毫无意义，还浪费机器资源；
  
• 本地 Debug 时，要么直接加断点，要么会翻日志文件，也基本不会检查控制台输出；
  
• 通过 main 函数跑测试代码时，一般直接用 System.out.println，不涉及日志系统；
  

十、无用的 LogUtil

最近我接手了一些项目，发现打印日志时使用了一个额外写的工具类 LogUtil。但细看代码，发现它只是把 Slf4j 或 Logback 已有能力又实现了一遍，包括但不限于：

1. 实现日志内容拼接，请见第三篇【3.1 info 方法】一节；
   
2. 实现日志参数默认转 JSON；
   
3. 日志超过最大长度截断，请见【6.1 限制日志文本最大长度】一节；
   
4. 将异常堆栈合并在同一行输出，请见【七、将堆栈合并为一行】一节；
   
5. 通过动态开关控制是否打印某些日志；
   
6. 日志中追加 traceId，请见第三篇【五、MDC】、第四篇【五、MDC 中的 traceId】两节；
   

所以，请抛弃 LogUtil，通过正确配置，「直面」 Slf4j 提供的强大 API 吧。

十一、熟读《日志规约》

《阿里巴巴Java开发手册》[2]有专门一章是《日志规约》[3]，建议熟读。其实整个《阿里巴巴Java开发手册》都应该熟读，花不了多少时间。

十二、一个小细节

请先看以下代码（假设没有添加【附1.1.1 场景一：参数自动转 JSON】中的能力）：

@Data
public class Foo {
    private String bar;
}

Foo foo = new Foo();
foo.setBar("baz");

// 方案一（注意第一个参数里的冒号）
log.info("foo:{}", foo);
// 输出 foo:Foo{bar=baz}

// 方案二（注意第一个参数里的等号）
log.info("foo={}", JSON.toJSONString(foo));
// 输出 foo={"bar":"baz"}

看出两者的区别了吗？

方案一使用了 Lombok 的 @ToString 转字符串，其中的 Key-Value 之间使用的等号 = 分隔，所以在前边建议使用冒号，从而在查看日志时可以更快分辨记录的信息。

同样的，方案二因为使用的 JSON 格式中 Key-Value 之间使用的冒号 : 分隔，所以前边建议使用等号。

参考链接：

[1]https://logback.qos.ch/manual/layouts.html#Evaluators

[2]https://github.com/alibaba/p3c

[3]https://github.com/alibaba/p3c/blob/master/p3c-gitbook/异常日志/日志规约.md

来源  |  阿里云开发者公众号

作者  |  尚左