Java 日志记录最佳实践，写得太好了吧！

作者：GeekerLou
来源：jianshu.com/p/546e9aace657

一、日志简介

1.1 日志是什么（WHAT）

日志：记录程序的运行轨迹，方便查找关键信息，也方便快速定位解决问题。

通常，Java程序员在开发项目时都是依赖Eclipse/IDEA等集成开发工具的Debug 调试功能来跟踪解决Bug，但项目发布到了测试、生产环境怎么办？你有可能会说可以使用远程调试，但实际并不能允许让你这么做。

所以，日志的作用就是在测试、生产环境没有 Debug 调试工具时开发和测试人员定位问题的手段。日志打得好，就能根据日志的轨迹快速定位并解决线上问题，反之，日志输出不好，不仅无法辅助定位问题反而可能会影响到程序的运行性能和稳定性。

很多介绍 AOP 的地方都采用日志来作为介绍，实际上日志要采用切面的话是极其不科学的！对于日志来说，只是在方法开始、结束、异常时输出一些什么，那是绝对不够的，这样的日志对于日志分析没有任何意义。如果在方法的开始和结束整个日志，那方法中呢？如果方法中没有日志的话，那就完全失去了日志的意义！如果应用出现问题要查找由什么原因造成的，也没有什么作用。这样的日志还不如不用！

1.2 日志有什么用（WHY）

不管是使用何种编程语言，日志输出几乎无处不再。总结起来，日志大致有以下几种用途：

  • 「问题追踪」：辅助排查和定位线上问题，优化程序运行性能。
  • 「状态监控」：通过日志分析，可以监控系统的运行状态。
  • 「安全审计」：审计主要体现在安全上，可以发现非授权的操作。

1.3 总结

日志在应用程序中是非常非常重要的，好的日志信息能有助于我们在程序出现 BUG 时能快速进行定位，并能找出其中的原因。

作为一个有修养的程序猿，对日志这个东西应当引起足够的重视。

二、日志框架（HOW）

2.1 常用的日志框架

log4j、Logging、commons-logging、slf4j、logback，开发的同学对这几个日志相关的技术不陌生吧，为什么有这么多日志技术，它们都是什么区别和联系呢？且看下文分解：

2.1.1 Logging

这是 Java 自带的日志工具类，在 JDK 1.5 开始就已经有了，在 java.util.logging 包下。通常情况下，这个基本没什么人用了，了解一下就行。

2.1.2 commons-logging

commons-logging 是日志的门面接口，它也是Apache 最早提供的日志门面接口，用户可以根据喜好选择不同的日志实现框架，而不必改动日志定义，这就是日志门面的好处，符合面对接口抽象编程。现在已经不太流行了，了解一下就行。

2.1.3 Slf4j

slf4j,英文全称为“Simple Logging Facade for Java”，为java提供的简单日志Facade。Facade门面，更底层一点说就是接口。它允许用户以自己的喜好，在工程中通过slf4j接入不同的日志系统。

因此slf4j入口就是众多接口的集合，它不负责具体的日志实现，只在编译时负责寻找合适的日志系统进行绑定。具体有哪些接口，全部都定义在slf4j-api中。查看slf4j-api源码就可以发现，里面除了public final class LoggerFactory类之外，都是接口定义。因此slf4j-api本质就是一个接口定义。

2.1.4 Log4j

Log4j 是 Apache 的一个开源日志框架，也是市场占有率最多的一个框架。

注意：log4j 在 2015.08.05 这一天被 Apache 宣布停止维护了，用户需要切换到 Log4j2上面去。

下面是官宣原文：

On August 5, 2015 the Logging Services Project Management Committee announced that Log4j 1.x had reached end of life. For complete text of the announcement please see the Apache Blog. Users of Log4j 1 are recommended to upgrade to Apache Log4j 2.

2.1.5 Log4j2

Log4j 2 Apache Log4j 2是apache开发的一款Log4j的升级产品。

Log4j2与Log4j1发生了很大的变化，log4j2不兼容log4j1。

2.1.6 Logback

Logback 是 Slf4j 的原生实现框架，同样也是出自 Log4j 一个人之手，但拥有比 log4j 更多的优点、特性和更做强的性能，现在基本都用来代替 log4j 成为主流。

Logback相对于log4j拥有更快的执行速度。基于我们先前在log4j上的工作，logback 重写了内部的实现，在某些特定的场景上面，甚至可以比之前的速度快上10倍。在保证logback的组件更加快速的同时，同时所需的内存更加少。

2.2 日志框架怎么选

选项太多了的后果就是选择困难症，我的看法是没有最好的，只有最合适的：

  • commons-loggin、slf4j 只是一种日志抽象门面，不是具体的日志框架。log4j、logback 是具体的日志实现框架。
  • 在比较关注性能的地方，选择Logback或自己实现高性能Logging API可能更合适。推荐：slf4j + logback.
  • 在已经使用了Log4j的项目中，如果没有发现问题，继续使用可能是更合适的方式：推荐组合为：slf4j + log4j2.
  • 如果不想有依赖则使用java.util.logging或框架容器已经提供的日志接口。

三、记录日志的时机

在看线上日志的时候，我们可曾陷入到日志泥潭？该出现的日志没有，无用的日志一大堆，或者需要的信息分散在各个角落，特别是遇到紧急的在线bug时，有效的日志被大量无意义的日志信息淹没，焦急且无奈地浪费大量精力查询日志。那什么是记录日志的合适时机呢？

总结几个需要写日志的点：

  • 「编程语言提示异常」：如今各类主流的编程语言都包括异常机制，业务相关的流行框架有完整的异常模块。这类捕获的异常是系统告知开发人员需要加以关注的，是质量非常高的报错。应当适当记录日志，根据实际结合业务的情况使用warn或者error级别。
  • 「业务流程预期不符」：除开平台以及编程语言异常之外，项目代码中结果与期望不符时也是日志场景之一，简单来说所有流程分支都可以加入考虑。取决于开发人员判断能否容忍情形发生。常见的合适场景包括外部参数不正确，数据处理问题导致返回码不在合理范围内等等。
  • 「系统核心角色，组件关键动作」：系统中核心角色触发的业务动作是需要多加关注的，是衡量系统正常运行的重要指标，建议记录INFO级别日志，比如电商系统用户从登录到下单的整个流程；微服务各服务节点交互；核心数据表增删改；核心组件运行等等，如果日志频度高或者打印量特别大，可以提炼关键点INFO记录，其余酌情考虑DEBUG级别。
  • 「系统初始化」：系统或者服务的启动参数。核心模块或者组件初始化过程中往往依赖一些关键配置，根据参数不同会提供不一样的服务。务必在这里记录INFO日志，打印出参数以及启动完成态服务表述。

四、日志打印最佳实践

4.1 日志变量定义

日志变量往往不变，最好定义成final static，变量名用大写。

private static final Logger log = LoggerFactory.getLogger({SimpleClassName}.getClass());

通常一个类只有一个 log 对象，如果有父类可以将 log 定义在父类中。

日志变量类型定义为门面接口（如 slf4j 的 Logger），实现类可以是 Log4j、Logback 等日志实现框架，不要把实现类定义为变量类型，否则日志切换不方便，也不符合抽象编程思想。

另外，推荐引入lombok的依赖，在类的头部加上@Slf4j的注解，之后便可以在程序的任意位置使用log变量打印日志信息了，使用起来更加简洁一点，在重构代码尤其是修改类名的时候无需改动原有代码。

4.2 参数占位格式

使用参数化形式{}占位，[]进行参数隔离

log.debug("Save order with order no：[{}], and order amount：[{}]");
log.debug("Save order with order no：[{}], and order amount：[{}]");

这种可读性好，这样一看就知道[]里面是输出的动态参数，{}用来占位类似绑定变量，而且只有真正准备打印的时候才会处理参数，方便定位问题。

如果日志框架不支持参数化形式，且日志输出时不支持该日志级别时会导致对象冗余创建，浪费内存，此时就需要使用 isXXEnabled 判断，如：

if(log.isDebugEnabled()){
    // 如果日志不支持参数化形式，debug又没开启，那字符串拼接就是无用的代码拼接，影响系统性能
    log.debug("Save order with order no：" + orderNo + ", and order amount：" + orderAmount);
}

至少 debug 级别是需要开启判断的，线上日志级别至少应该是 info 以上的。

这里推荐大家用 SLF4J 的门面接口，可以用参数化形式输出日志，debug 级别也不必用 if 判断，简化代码。

4.3 日志的基本格式

日志输出主要在文件中，应包括以下内容：

  • 日志时间
  • 日志级别主要使用
  • 调用链标识（可选）
  • 线程名称
  • 日志记录器名称
  • 日志内容
  • 异常堆栈（不一定有）
11:44:44.827 WARN [93ef3E0120160803114444] [main] [ClassPathXmlApplicationContext] Exception encountered during context initialization - cancelling refresh attempt

4.3.1 日志时间

作为日志产生的日期和时间，这个数据非常重要，一般精确到毫秒。由于线上一般配置为按天滚动日志文件，日期标识在文件名上，所以可以不放在这个时间中，使用 HH:mm:ss.SSS 格式即可。非要加上也未尝不可，格式推荐：yyyy-MM-dd HH:mm:ss.SSS。

4.3.2 日志级别

日志的输出都是分级别的，不同的设置不同的场合打印不同的日志。下面拿最普遍用的 Log4j 日志框架来做个日志级别的说明，这个也比较齐全，其他的日志框架也都大同小异。

主要使用如下的四个级别：

  • DEBUG：DEUBG 级别的主要输出调试性质的内容，该级别日志主要用于在开发、测试阶段输出。该级别的日志应尽可能地详尽，开发人员可以将各类详细信息记录到DEBUG里，起到调试的作用，包括参数信息，调试细节信息，返回值信息等等，便于在开发、测试阶段出现问题或者异常时，对其进行分析。
  • INFO：INFO日志主要记录系统关键信息，旨在保留系统正常工作期间关键运行指标，开发人员可以将初始化系统配置、业务状态变化信息，或者用户业务流程中的核心处理记录到INFO日志中，方便日常运维工作以及错误回溯时上下文场景复现。建议在项目完成后，在测试环境将日志级别调成 INFO，然后通过 INFO 级别的信息看看是否能了解这个应用的运用情况，如果出现问题后是否这些日志能否提供有用的排查问题的信息。
  • WARN：WARN 级别的主要输出警告性质的内容，这些内容是可以预知且是有规划的，比如，某个方法入参为空或者该参数的值不满足运行该方法的条件时。在 WARN 级别的时应输出较为详尽的信息，以便于事后对日志进行分析
  • ERROR：ERROR 级别主要针对于一些不可预知的信息，诸如：错误、异常等，比如，在 catch 块中抓获的网络通信、数据库连接等异常，若异常对系统的整个流程影响不大，可以使用 WARN 级别日志输出。在输出 ERROR 级别的日志时，尽量多地输出方法入参数、方法执行过程中产生的对象等数据，在带有错误、异常对象的数据时，需要将该对象一并输出

4.3.2.1 INFO和DEBUG的选择

DEBUG级别比INFO低，包含调试时更详细的了解系统运行状态的东西，比如变量的值等等，都可以输出到DEBUG日志里。INFO是在线日志默认的输出级别，反馈系统的当前状态给最终用户看的。输出的信息，应该对最终用户具有实际意义的。从功能角度上说，Info输出的信息可以看作是软件产品的一部分，所以需要谨慎对待，不可随便输出。尝试记录INFO日志时不妨在头脑中模拟线上运行，如果这条日志会被频繁打印或者大部分时间对于纠错起不到作用，就应当考虑下调为DEBUG级别。

  • 由于info及debug日志打印量远大于ERROR，出于前文日志性能的考虑，如果代码为核心代码，执行频率非常高，务必推敲日志设计是否合理，是否需要下调为DEBUG级别日志。
  • 注意日志的可读性，不妨在写完代码review这条日志是否通顺，能否提供真正有意义的信息。
  • 日志输出是多线程公用的，如果有另外一个线程正在输出日志，上面的记录就会被打断，最终显示输出和预想的就会不一致。

4.3.2.2 WARN,ERROR的选择

当方法或者功能处理过程中产生不符合预期结果或者有框架报错时可以考虑使用，常见问题处理方法包括：

  • 增加判断处理逻辑，尝试本地解决：增加逻辑判断吞掉报警永远是最优选择。
  • 抛出异常，交给上层逻辑解决
  • 记录日志，报警提醒
  • 使用返回码包装错误做返回

一般来说，WARN级别不会短信报警，ERROR级别则会短信报警甚至电话报警，ERROR级别的日志意味着系统中发生了非常严重的问题，必须有人马上处理，比如数据库不可用，系统的关键业务流程走不下去等等。错误的使用反而带来严重的后果，不区分问题的重要程度，只要有问题就error记录下来，其实这样是非常不负责任的，因为对于成熟的系统，都会有一套完整的报错机制，那这个错误信息什么时候需要发出来，很多都是依据单位时间内ERROR日志的数量来确定的。因此如果我们不分轻重缓急，一律ERROR对待，就会徒增报错的频率，久而久之，我们的救火队员对错误警报就不会那么在意，这个警报也就失去了原始的意义。

WARN代表可恢复的异常，此次失败不影响下次业务的执行，开发人员会苦恼某些场景下几次失败可容忍，频率高的时候需要提醒，记录ERROR的结果是线上时不时出现容忍范围内的报警，这时报警是无意义的。但反之不记录ERROR日志，真正出现问题则不会有实时报警，错过最佳处理时机。

强调ERROR报警

  • ERROR级别的日志打印通常伴随报警通知。ERROR的报出应该伴随着业务功能受损，即上面提到的系统中发生了非常严重的问题，必须有人马上处理。

ERROR日志目标

  • 给处理者直接准确的信息：error信息形成自身闭环。

问题定位：

  • 发生了什么问题，哪些功能受到影响
  • 获取帮助信息：直接帮助信息或帮助信息的存储位置
  • 通过报警知道解决方案或者找何人解决

日志模板

log.error(“[接口名或操作名] [Some Error Msg] happens. [Probably Because]. [Probably need to do] [params] .”);
log.error(“[接口名或操作名] [Some Error Msg] happens. [Probably Because]. [please contact xxx@xxx] [params] .”);

4.3.3 调用链标识

在分布式应用中，用户的一个请求会调用若干个服务完成，这些服务可能还是嵌套调用的，因此完成一个请求的日志并不在一个应用的日志文件，而是分散在不同服务器上不同应用节点的日志文件中。该标识是为了串联一个请求在整个系统中的调用日志。

调用链标识格式：

  • 唯一字符串（trace ID）
  • 调用层级（span ID）

调用链标识作为可选项，无该数据时只输出 [] 即可。

4.3.4 线程名称

输出该日志的线程名称，一般在一个应用中一个同步请求由同一线程完成，输出线程名称可以在各个请求产生的日志中进行分类，便于分清当前请求上下文的日志。

4.3.5 日志记录器名称

日志记录器名称一般使用类名，日志文件中可以输出简单的类名即可，看实际情况是否需要使用包名和行号等信息。主要用于看到日志后到哪个类中去找这个日志输出，便于定位问题所在。

4.3.6 日志内容

  • 禁用 System.out.println和System.err.println
  • 变参替换日志拼接
  • 输出日志的对象，应在其类中实现快速的 toString 方法，以便于在日志输出时仅输出这个对象类名和 hashCode
  • 预防空指针:不要在日志中调用对象的方法获取值，除非确保该对象肯定不为 null，否则很有可能会因为日志的问题而导致应用产生空指针异常。
// 不推荐
log.debug( "Load student(id={}), name: {}" , id , student.getName() );

// 推荐
log.debug( "Load student(id={}), student: {}" , id , student );

对于一些一定需要进行拼接字符串，或者需要耗费时间、浪费内存才能产生的日志内容作为日志输出时，应使用 log.isXxxxxEnable() 进行判断后再进行拼接处理，比如：

if (log.isDebugEnable()) {
    StringBuilder builder = new StringBuilder();
    for (Student student : students) {
        builder.append("student: ").append(student);
    }
    builder.append("value: ").append(JSON.toJSONString(object));
    log.debug( "debug log example, detail: {}" , builder );
}

4.3.7 异常堆栈

异常堆栈一般会出现在 ERROR 或者 WARN 级别的日志中，异常堆栈含有方法调用链的系统，以及异常产生的根源。异常堆栈的日志属于上一行日志的，在日志收集时需要将其划至上一行中。

4.4 日志文件

日志文件放置于固定的目录中，按照一定的模板进行命名，推荐的日志文件名称：

当前正在写入的日志文件名：<应用名>[-<功能名>].log
已经滚入历史的日志文件名：<应用名>[-<功能名>].log.<yyyy-MM-dd>

4.5 日志配置

根据不同的环境配置不同的日志输出方式：

  • 本地调试可以将日志输出到控制台上
  • 测试环境或者生产环境输出到文件中，每天产生一个文件，如果日志量庞大可以每个小时产生一个日志文件
  • 生产环境中的文件输出，可以考虑使用异步文件输出，该种方式日志并不会马上刷新到文件中去，会产生日志延时，在停止应用时可能会导致一些还在内存中的日志未能及时刷新到文件中去而产生丢失，如果对于应用的要求并不是非常高的话，可暂不考虑异步日志

logback 日志工具可以在日志文件滚动后将前一文件进行压缩，以减少磁盘空间占用，若使用 logback 对于日志量庞大的应用建议开启该功能。

4.6 日志使用规范

  1. 在一个对象中通常只使用一个Logger对象，Logger应该是static final的，只有在少数需要在构造函数中传递logger的情况下才使用private final。
private static final Logger log = LoggerFactory.getLogger(Main.class);
  1. 不要使用具体的日志实现类
InterfaceImpl interface = new InterfaceImpl();

这段代码大家都看得懂吧？应该面向接口的对象编程，而不是面向实现，这也是软件设计模式的原则，正确的做法应该是。

Interface interface = new InterfaceImpl();

日志框架里面也是如此，上面也说了，日志有门面接口，有具体实现的实现框架，所以大家不要面向实现编程。

  1. 输出Exceptions的全部Throwable信息。因为log.error(msg)和log.error(msg,e.getMessage())这样的日志输出方法会丢失掉最重要的StackTrace信息。
void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        log.error(e.getMessage());//错误示范
        log.erroe("Bad Things",e.getMessage());//错误示范
        log.error("Bad Things",e);//正确演示
    }
}
  1. 不允许记录日志后又抛出异常。如捕获异常后又抛出了自定义业务异常，此时无需记录错误日志，由最终捕获方进行异常处理。不能又抛出异常，又打印错误日志，不然会造成重复输出日志。
void foo() throws LogException{
    try{
        //do somehing 
    }catch(Exception e){
        log.error("Bad Things",e);//正确
        throw new LogException("Bad Things",e);
    }
}
  1. 不允许使用标准输出

包括System.out.println()和System.error.println()语句。因为这个只会打印到控制台，而不会记录到日志文件中，不方便管理日志。此外，标准输出不会显示类名和行号信息，一旦代码中大量出现标准输出的代码，且日志中打印有标准输出的内容，很难定位日志内容和日志打印的位置，根本无法排查问题，想删除无用日志输出也改不动，这个是笔者在重构古董代码的时候亲自踩过的一个坑。

void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        Syste.out.println(e.getMessage());//错误
        System.error.println(e.getMessage());//错误
        log.error("Bad Things",e);//正确
    }
}
  1. 不允许出现printStackTrace
void foo(){
    try{
       //do somehing 
    }catch(Exception e){
        e.printStacktrace();//错误
        log.error("Bad Things",e);//正确
    }
}

来看一下它的源码：

public void printStackTrace() {
    printStackTrace(System.err);
}

它其实也是利用 System.err 输出到了Tomcat控制台。

  1. 禁止在线上环境开启debug级别日志输出

出于日志性能的考虑，如果代码为核心代码，执行频率非常高，则输出日志建议增加判断，尤其是低级别的输出<debug、info、warn>。

一是因为项目本身 debug 日志太多，二是各种框架中也大量使用 debug 的日志，线上开启 debug 不久就会打满磁盘，影响业务系统的正常运行。

  1. 不要在大循环中打印日志

如果你的框架使用了性能不高的 Log4j 框架，那就不要在上千个 for 循环中打印日志，这样可能会拖垮你的应用程序，如果你的程序响应时间变慢，那要考虑是不是日志打印的过多了。

for(int i=0; i<2000; i++){
    log.info("XX");
}

最好的办法是在循环中记录要点，在循环外面总结打印出来。

  1. 打印有意义的日志

通常情况下在程序日志里记录一些比较有意义的状态数据：程序启动，退出的时间点；程序运行消耗时间；耗时程序的执行进度；重要变量的状态变化。

五、参考资料

  1. Java 程序如何正确地打日志
  2. Java 应用中的日志
  3. 优秀日志实践准则
  4. Java常用日志框架介绍

近期热文推荐：

1.1,000+ 道 Java面试题及答案整理(2021最新版)

2.别在再满屏的 if/ else 了，试试策略模式，真香！！

3.卧槽！Java 中的 xx ≠ null 是什么新语法？

4.Spring Boot 2.5 重磅发布，黑暗模式太炸了！

5.《Java开发手册（嵩山版）》最新发布，速速下载！

觉得不错，别忘了随手点赞+转发哦！

posted @ 2021-11-13 16:29  Java技术栈  阅读(4258)  评论(0)  编辑  收藏  举报