我的 Java 日志记录最佳实践

为什么是日志?

对于大多数后端开发来说,日志可能是应用程序给予你反馈的唯一方式。在开发环境,你通常能用 Idea 之类的集成开发工具进行 DeBug 调试,但是在生产环境呢?部分人也许用过远程调试,但生产环境原则上来讲,是不允许你进行任何调试操作的。所以,拥有一份便于查看的日志,对排查问题相当重要。

日志的好处往往在一个系统中是被低估的,甚至很多人根本不重视它。人写日记,是为了记录每一天都干了些什么,而软件的日志,应当如此。作为一名优秀的软件开发工程师,我们应该利用好日志来解决问题,并辅助了解整个系统的健康状况。

如果你对日志还没有系统性的了解,或者不清楚什么是日志,可以参考 Wiki 百科的 日志文件 词条,一步步去了解。

我的最佳实践

以下是我的 Java 日志记录最佳实践。

日志信息的优化

日志虽然能帮助我们排查线上问题,但是日志信息太多的话,也并不是一件好事。所以,结合你自己的系统和业务,对日志记录的繁简程度恰到好处,是一件并不容易的事情。

方法之后

弄清楚这个标题之前,我们得先明确一件事——日志在业务中用来记录已经发生的事情。我来举一个通用的例子吧:

1
2
3
4
5
6
7
// 方法之前打印日志
log.info("准备执行登录操作.[loginParam={}]", loginParam);
userService.login(loginParam);

// 方法之后打印日志
String result = userService.login(loginParam);
log.info("登录执行完成.[result={}]", result);

首先,登录方法,可能是执行了服务间的调用,或者是本地方法。我们从第一个日志是看不出 login() 是否调用成功的,在某些情况下,可能无法产生任何有效的信息。比如说你【没注意到】被调用方抛出的异常、或者说压根就没有做异常处理(相信不少人有过这种经历),那么你这时候就会陷入怀疑之中,根本看不出来是什么情况导致的。

这种情况我是真的碰到过,可能是经验不足导致的,以至于后来专门去了解了日志的相关知识。在这之前,我确实也比较容易忽略它的重要性。

我们再来看第二个日志,当我们看到它的时候,说明它之前的操作是已经成功了。如果说调用失败了,那么你是看不到日志的,应该能直接看到异常。

不同架构下的日志

在传统的单体项目中,我们一般只需对一次请求间经过的所有日志都加上【唯一的 id】—— RequestID,将所有执行过程串联起来。

在 SOA/微服务 等架构下,情况就有所不同了,因为我们需要考虑到服务之间的可跟踪性。比如说我们需要在一个【统一的入口】,使用【唯一的请求标识符】,标记这次请求所执行到的所有的日志。这样才能对日志进行跟踪,虽然每个服务直接打印的日志信息,在海里日志信息里面没有什么特别的关联。但是当我们清洗日志数据之后,可以根据【唯一标识符】,去筛选出所有相关的日志信息。

一般的,我们会用 Elasticsearch 或者 Clickhouse 存储日志,用 Kibana 或者 Grafana 来进行日志分析。这时你会发现,在排查线上问题的过程中,你只要找到对应请求的【唯一标识符】,你就能迅速在海量日志中,找到对应的信息。

分离参数和消息

开发中比较常见的日志类型,主要有两种,一种是咱们自定义的日志消息,另一种是业务参数,当然,可能还有异常信息之类的。下面是一个简单的例子:

1
2
3
4
5
6
7
// 没有分开的情况
restTemplate.getForObject(url, String.class, vars);
log.info("请求路径:{}成功啦!", url);

// 分开的情况
restTemplate.getForObject(url, String.class, vars);
log.info("请求成功啦![url={}]", url);

咋一看上去,2 种日志格式,似乎没多大区别。但实际上,第一种在某些情况下增加了阅读难度,我们不妨想一下,在开发中,是否有碰到过提示消息很长的日志语句?或者是业务参数特别的长,这种情况下将业务参数放在末尾是否更好呢?而且如果要添加新参数的话,重写起来相对而言也更麻烦不是吗?当然,第一种可能从某些角度来说,写起来会爽一些。

如果说你接触过 LogStash 的话,那么你应该了解 Grok 插件,第一种写法,将会导致Grok 模式的解析变得更加困难,而第二种写法,就不存在这种情况,因为语法很清晰。

日志格式的优化

拿 SpringBoot 项目来举例说明,一般我们会在对应的 xml 文件中配置日志的输出格式。这些文件可能是 logback-spring.xmllog4j2.xml 等。

日志格式结构化

一般来说,日志输出文件中,主要会包含如下内容:

  • 日志打印时间
  • 日志输出级别
  • 自定义的【唯一标识】
  • 线程名称
  • 调用链标识
  • 日志内容
  • 程序异常堆栈
pattern="[%d{yyyy-MM-dd HH:mm:ss}] %-5level {requestId=%X{requestId}} %class{36} %L %M - %msg%xEx%n"

我们可以看到这个例子,开头是日志时间、其次是日志级别、然后是 requestId ,消息放在了最后。实际上格式并没有太多特殊的要求,更多的是你需要结合项目自身情况,和你的团队成员共同制定应该用什么格式。

日志级别控制

日志级别有 8 种,去掉全部显示和全部关闭,还剩如下 6 个级别:

  • TRACE — TRACE 级别指定比 DEBUG 更细粒度的信息事件,因为级别很低,所以一般用不到。
  • DEBUG — DEBUG 级别指定对调试应用程序最有用的细粒度信息事件,一般用于开发过程中打印运行(技术)信息。
  • INFO — INFO 级别指定信息消息,在粗粒度级别突出显示应用程序的进度,一般用于打印业务信息。
  • WARN — WARN 级别表示潜在的有害情况,一些特定的错误信息,也会是一些提示。
  • ERROR — ERROR 级别指定可能仍允许应用程序继续运行的错误事件,一般打印错误和异常信息。
  • FATAL — FATAL 级别指定可能导致应用程序中止的非常严重的错误事件。

一般来说,DEBUG 和 INFO、WARN 和 ERROR 容易混淆。在一个开发团队中,通常日志级别的设定标准是需要达成一致的,可以参考 [The Syslog Protocol](The Syslog Protocol)。最好是对不同级别的日志,定义不同的输出格式,而不是由开发人员自由发挥。

日志性能优化

我们要确保在打印日志时不会增加额外的系统响应时间,毕竟有些地方的日志是必须的。尽可能以异步方式写入日志,可以先写入到本地日志文件,再使用日志转发器发送给相应的服务,也可以使用消息队列,但这种方式可能会存在延迟,不过相对于对业务性能的影响而言,都是可以接受的。

日志输出文件

我们需要将不同的日志输出到不同的文件,因为不是很多小伙伴参与的项目,都是使用了诸如 ELK 之类的东西。这时候为了方便对线上错误进行分析,如果所有的错误日志同时被输出到了一个单独的文件之中,那么排查起来将会省事很多。

一些场景下的使用规范

  • 使用标准的日志对象,而不是直接创建日志实现类。
1
2
3
4
5
// 在类上面加上注解
@Slf4j

// 或者直接使用下面这行代码创建
private static final Logger log = LoggerFactory.getLogger(Main.class);

面向接口编程,而不是面向实现,这是软件设计模式之一。上面 2 种方式,实现的效果是一样的(编译后再看你就明白了),在项目中统一使用某一种即可!

  • 不推荐标准输出
1
2
3
4
5
6
7
try {
    // todo
} catch (Exception ex) {
    Syste.out.println(ex.getMessage()); // 不推荐
    System.err.println(ex.getMessage()); // 不推荐
    log.error("error message", ex); // 推荐
}
  • 不推荐 printStacktrace
1
2
3
4
5
6
try {
    // todo
} catch (Exception ex) {
    ex.printStacktrace(); // 不推荐
    log.error("error message", ex); // 推荐
}

这个 printStacktrace() 几乎所有人都用过,不知道大家有没有点进去看过一眼源码,实际上跟上面那一条说的道理是一样的。

1
2
3
public void printStackTrace() {
    printStackTrace(System.err);
}
  • 注意不要输出掉了关键信息
1
2
3
4
5
6
7
try {
    // todo
} catch (Exception ex) {
    log.error(ex.getMessage()); // 不推荐
    log.error("error message", ex.getMessage()); // 不推荐
    log.error("error message", ex); // 推荐
}

这种 ex.getMessage() 写法,我在不少项目见过,曾经我也经常用,但随着学习的深入,发现这样做其实并不太好。因为这样的日志输出方式,往往会丢失掉最重要的 StackTrace 信息。

  • 日志异常二选一
1
2
3
4
5
6
try {
    // todo
} catch (Exception ex) {
    log.error("error message", ex); // 两者冲突
    throw new RuntimeException(ex); // 推荐
}

如果捕获异常后,因为业务需求,需要再次往外抛异常,那么可以不用写上面那句错误日志。因为这种情况下,异常都是交由最终捕获方去进行了处理的,很容易造成重复日志输出。你想一想,全局异常处理的地方,是不是会单独打印一条错误日志?当然,还得看项目本身的实际情况,这里只是推荐二选一。

  • 别 TM 在循环中打印日志了 🥲
1
2
3
for (int i=0; i < vars.size(); i++) {
    log.info("不要在循环中打日志!!!");
}

注意上面这个循环,如果循环次数很多,想象一下,是不是会产生很多无意义的日志?而且可能会影响程序的性能!

最后

想玩转日志,要注意的点有很多,日志容易被人们忽略,但它也很重要。日志跟踪、日志聚合、日志指标等等,都有不少知识点。这篇文章汇集了我自 20 年毕业到现在以来,对于日志系统而言踩过的坑,以及一些学习的总结。当然,要学的还有很多,不同团队、不同项目采用的方案也不同。但是你对日志系统有一个全面的认识之后,不管面对哪一种情况,你都能游刃有余。哪怕是参与到团队日志规范的制定,你也不会听的云里雾里,甚至可以提出你自己的观点。全面认知过日志系统后,你也能大幅度减轻你和同事对线上问题排查的负担。

当然,还有更多关于日志的内容,我这里没有写,如果你想了解,请善用搜索引擎。

扩展阅读:美团技术团队:如何优雅地记录操作日志?

updatedupdated2022-08-252022-08-25