首页   

Java日志通关(五) - 最佳实践

阿里云开发者  · 科技公司  · 1 月前

阿里妹导读


作者日常在与其他同学合作时,经常发现不合理的日志配置以及五花八门的日志记录方式,后续作者打算在团队内做一次Java日志的分享,本文是整理出的系列文章第五篇。

一、总是使用接口层

无论是写代码还是实现一个三方工具,请只使用接口层记录日志。
如果需要向外提供三方工具,记得在依赖中将日志的实现层及适配层标记为 optional,比如:
<dependency>  <groupId>ch.qos.logbackgroupId>  <artifactId>logback-coreartifactId>  <version>${logback.version}version>  <scope>runtimescope>  <optional>trueoptional>dependency>

简单解释一下:

  • runtime:runtime 的包编译时会被忽略(认为运行环境已经有对应包了);
  • true:依赖不会传递,Maven 不会自动安装此包;

二、不要打印分隔线

不要打印类似这种只包含分隔线的内容:log.info("========== start =========="),因为在茫茫的日志中,这句日志的下一条很可能来自其他异步任务,如果使用 SLS 收集甚至来自另一台机器,这条分隔线根本起不到任何作用。
正确的方式是通过关键字进行标记,比如:log.info("FooBarProcessor start, request={}", request),之后就可以通过关键字 FooBarProcessor 快速过滤,这对于 grep 和 SLS 都适用。
另外,可以用 Marker 让日志语义更清晰(可以参考第三篇中【四、Marker】节),只是麻烦了点儿,看个人喜好。

三、避免因写日志而抛错

比如没有判空就直接调用了它的方法:
Object result = rpcResource.call();
// 如果 result 为 null 会抛 NPElog.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 参数:
@Datapublic 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】中的能力):
@Datapublic 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

推荐文章
白鲸出海  ·  GPT-4o ...  ·  昨天  
腾讯  ·  《狂镖2》:暑假去哪  ·  4 天前  
腾讯  ·  腾讯又招「老师」,13岁以上可报名  ·  6 天前  
勤智资本  ·  勤智生态 | ...  ·  1 年前  
人工智能那点事  ·  欧盟放宽燃油车禁令 日本车企也松口气  ·  1 年前  
丁香医生  ·  血脂高就不能吃油?控制血脂的 4 ...  ·  4 年前  
© 2022 精读
删除内容请联系邮箱 2879853325@qq.com