Java 日志最佳实践

原文标题:Java日志通关(五) - 最佳实践

原文作者:阿里云开发者

冷月清谈:

**要点一:使用接口层记录日志** - 只使用接口层记录日志,避免使用实现层和适配层。

要点二:避免打印分隔线

  • 使用关键字标记日志,方便快速过滤。

要点三:避免因写日志而抛错

  • 判空后再调用方法,避免 NPE。

要点四:使用 Fastjson 参数

  • 使用 IgnoreErrorGetter 参数忽略 getter 中的异常。
  • 使用 IgnoreNonFieldGetter 参数忽略没有实体字段对应的 getter 方法。

要点五:不要遗漏异常堆栈

  • 将异常参数不占用字符模板,保证异常堆栈输出完整。

要点六:限制日志输出长度

  • 使用格式修饰符限制日志文本和堆栈层级。

要点七:将堆栈合并为一行

  • 使用 Logback 配置将堆栈合并为一行。

要点八:不建议使用 %method 和 %line

  • 获取堆栈轨迹消耗资源,建议使用其他方式输出方法名和行号。

要点九:不要将日志输出至控制台

  • 控制台输出的日志无人关注,浪费资源。

要点十:抛弃 LogUtil

  • Slf4j 和 Logback 已提供所需功能,不应再使用 LogUtil。

要点十一:熟读日志规约

  • 参考《阿里巴巴Java开发手册》中的日志规约。

要点十二:注意 Key-Value 分隔符

  • 使用冒号或等号分隔 Key-Value,根据输出格式而定。



怜星夜思:


1、如何判断一个 getter 方法抛出的异常是否是严重问题?
2、为什么建议将堆栈合并为一行输出?
3、在 Logback 中,如何只打印前 50 层堆栈,并将其转换为一行输出?

原文内容

阿里妹导读


作者日常在与其他同学合作时,经常发现不合理的日志配置以及五花八门的日志记录方式,后续作者打算在团队内做一次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

一般来说,如果 getter 方法抛出的异常是由于对象状态不一致或配置错误导致的,则可以认为是严重问题。例如,如果一个 getter 方法试图访问一个不存在的属性,或者试图解析一个无效的配置值,则这些异常可能是严重问题的征兆。

当然,合并堆栈也有一些缺点。例如,它可能会使日志看起来更紧凑,使得在文本编辑器或日志查看器中浏览起来更困难。此外,对于非常复杂的堆栈,可能难以在合并后识别各个调用。因此,在决定是否合并堆栈时,权衡利弊非常重要。

另一方面,如果 getter 方法抛出的异常是由于瞬态条件或用户错误导致的,则可能不一定是严重问题。例如,如果一个 getter 方法试图访问一个尚未初始化的属性,或者试图转换一个无效的用户输入,则这些异常通常可以忽略,不会影响系统的整体稳定性。

此外,合并的堆栈可以在日志聚合系统中节省空间。当日志被发送到中央存储库时,每一行都代表一个单独的事件,这可能会占用大量空间。通过合并堆栈,可以减少日志大小,从而节省存储和带宽成本。

最终,判断一个 getter 方法抛出的异常是否是严重问题的最佳方法是考虑异常的根本原因和对系统的影响。如果异常表明存在可能导致系统不稳定或数据丢失的潜在问题,则应将其视为严重问题。如果异常不太可能对系统造成重大影响,则可以将其忽略。不过,建议谨慎行事,并在做出决定之前仔细考虑异常的潜在后果。

这种配置不仅可以将堆栈限制为 50 层,还可以将其合并为一行输出。这对于通过管道进行多层 grep 和快速定位问题非常有用。

将堆栈合并为一行输出的主要好处是便于日志分析。当堆栈分散在多行时,很难快速查看和理解错误的来源。一行输出可以更轻松地通过管道(|)进行多层 grep,从而帮助用户更快地定位问题。

可以使用以下 Logback 配置实现:<pattern>%.-5000replace(%exception{50}){'[ ]+', ' '}%nopex</pattern>。其中,%.-5000 限制日志文本的最大长度为 5000 个字符,replace(%exception{50}){'[ ]+', ' '} 将异常堆栈中的换行、回车和制表符替换为空格,%nopex 确保 Logback 不会自动在日志最后追加原始异常堆栈。

需要注意的是,此配置只能用于 Logback 1.2.3 及更高版本。对于较早版本的 Logback,可以使用<pattern>%.-50exception{50}</pattern> 配置来仅打印前 50 层堆栈,但无法将其合并为一行输出。