我的 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.xml、log4j2.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 年毕业到现在以来，对于日志系统而言踩过的坑，以及一些学习的总结。当然，要学的还有很多，不同团队、不同项目采用的方案也不同。但是你对日志系统有一个全面的认识之后，不管面对哪一种情况，你都能游刃有余。哪怕是参与到团队日志规范的制定，你也不会听的云里雾里，甚至可以提出你自己的观点。全面认知过日志系统后，你也能大幅度减轻你和同事对线上问题排查的负担。

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

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

我的 Java 日志记录最佳实践

相关文章：