跳至主要內容

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

悟空约 2187 字大约 7 分钟...

img
img

阿里妹导读

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

一、总是使用接口层

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

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

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

简单解释一下:

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

二、不要打印分隔线

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

正确的方式是通过关键字进行标记,比如:log.infoopen in new window("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
换行后会有堆栈信息
%.-2000message

六、限制日志输出长度

6.1 限制日志文本最大长度

有时候一个 POJO 非常大,当我们通过 :

log.infoopen in new window("result={}", JSON.toJSONString(result))

打印日志时,整条日志就会变得很长。不但对性能会有影响,主要这么大的结果对实际问题排查也不见得有帮助。

可以参考第四篇【3.2 Format modifiers】来限制消息最大长度,并将超出的部分丢弃:

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

6.2 限制堆栈的层级

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

七、将堆栈合并为一行

有些同学希望将堆栈在一行输出,保证通过管道(|)进行多层 grep 时捞到期望的记录。

其实通过 Logback 配置就可以支持这个能力,主要用到我们在 【4.3.1 Conversion Word】中提过的 %replace:

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

简单说明一下:

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

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

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

即:

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

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

在 Logback 的配置中,可以通过 %method 和 %line 输出方法名和行号。但这两项依赖于当前的堆栈轨迹 (StackTrace) ,而获取堆栈轨迹的代价比较高,日志一多就会占用大量的 CPU,所以一般情况不建议在日志中输出这些字段。

如果对方法名有输出要求,可以直接硬编码到输出字符串中,比如:

@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"}

九、不要将日志输出至 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】中的能力):


看出两者的区别了吗?

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

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

参考链接:

[1]https://logback.qos.ch/manual/layouts.html#Evaluatorsopen in new window

[2]https://github.com/alibaba/p3copen in new window

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

全文完

本文由 简悦 SimpReadopen in new window 优化,用以提升阅读体验

使用了 全新的简悦词法分析引擎 beta,点击查看open in new window详细说明

评论
  • 按正序
  • 按倒序
  • 按热度
Powered by Waline v3.3.0