JAVA 应用日志最佳实践

原创

鲍远林

修改于 2020-09-14 13:17:41

2.9K0

修改于 2020-09-14 13:17:41

文章被收录于专栏：泛互云原生泛互云原生

1. 常见的 Java 日志框架及选择

Java 界的日志解决方案很多，让人眼花缭乱，但常用的包括 JUL，JCL，SLF4J，Logback，Log4j / Log4j2 等。

JUL 自 JDK 1.5 开始，java.util.logging（JUL）包下就提供了内置的日志工具类，功能比较简单，一般没人使用。
Apache Commons-Logging Apache Commons-logging 也被称作 Jakarta Commons-Logging（JCL）最早提供了日志门面接口，采用 facade 模式更符合面向接口的抽象编程方式，使得用户可以自由选择不同的日志实现框架，而不必改动具体的日志语句。14年后没再更新，JCL 的风光早已不在。
SLF4J SLF4J（The Simple Logging Facade for Java ）是一个简单的日志门面，类似 Commons-logging，通过 Facade Pattern 提供一些 Java logging API。SLF4J 的 slf4j-api 包中提供了众多日志接口定义，它只服务于各种各样的日志框架而不负责具体的日志实现，只在编译时负责寻找合适的日志系统进行绑定。作者创建 SLF4J 的目的是为了替代 JCL。
Logback Logback 是由 Log4j 创始人设计的又一个开源日记组件，是 Slf4j 的原生实现框架，相比 log4j，logback 拥有更快的执行速度，在 Log4j2 出来前的很长一段时间里都是 java 日志界的主流。
Log4j & Log4j2 Log4j 和 Log4j2 也都是 Apache 的开源日志框架，Log4j 2.0 以后的版本称为 Log4j2 是 Log4 1.x 的升级版，Log4j 1.x 版在 2015.08.05 停止维护了。Log4j2 参考了 Logback 的一些优秀的设计，并修复了老版的问题，整体提升很大，特别是异步方面的性能提升。 Log4j2 与 Log4j 发生了很大的变化，log4j2 不兼容 Log4j。

JCL、SLF4J 只是一种日志抽象门面，不是具体的日志框架；Logback、Log4j/Log4j2 是具体的日志实现框架。在选择一个日志框架时可考虑以下两点：

具有日志缓冲区的框架可以减少频繁的文件 I/O 操作，对性能提升显著；
支持异步日志功能的框架，不会阻塞其它应用线程，因而是首选；

Logback 和 Log4j2 都支持以上特性，在关注性能的地方，推荐使用 slf4j + log4j2 或 slf4j + logback。如果不想任何额外的依赖，则使用 JUL 或容器框架已经提供的日志接口。

2. 日志级别

Java 日志框架一般都提供了以下日志级别，缺省级别为 INFO：

FATAL : 最严重的日志级别，必须慎用。出现该级别日志时，表示服务不可用，需要研发或运维立即接入，比如程序崩溃、无法启动、OOM 等；
ERROR : 紧急程度要低于FATAL，出现 ERROR 时，已经影响了用户的正常访问，要马上处理，比如应用连接不上数据库；
WARN : 临时性问题或未预期的用户行为，不会对系统功能产生重大影响，比如用户登录失败，网络波动等；
INFO : 记录系统的正常运行状态下有意义的事件，比如用户下单，新用户注册等；
DEBUG : 调试信息，可记录详细的业务处理到哪一步了，以及当前的变量状态；
TRACE : 类似 DEBUG，但记录更详细的跟踪信息；

常用日志框架间的级别对应关系见下表：

SLF4J	Log4j	Log4j2	Logback	JUL
FATAL	FATAL	FATAL
ERROR	ERROR	ERROR	ERROR	SEVERE
WARN	WARN	WARN	WARN	WARNING
INFO	INFO	INFO	INFO	INFO, CONFIG
DEBUG	DEBUG	DEBUG	DEBUG	FINE, FINER
TRACE	TRACE	TRACE	TRACE	FINEST

3. 最佳日志实践

1. 日志的基本格式

基本的日志格式需要输出：时间、级别、线程名称、logger 名称、日志内容。如果能拿到调用链 ID 的话，输出到日志中对问题的定位帮助很大。出现异常时，将异常堆栈输出到日志也是非常有必要的。日志产生的日期和时间非常重要，一般精确到毫秒，推荐格式 yyyy-MM-dd HH:mm:ss.SSS。通常线上日志配置了按天滚动，日志文件名带有日期，此时使用 HH:mm:ss.SSS 格式即可。

2. 使用门面模式的日志框架（比如流行的 SLF4J）而不要直接使用具体日志实现框架。

一方面面向接口编程更优雅；另一方面便于统一使用方式和日后的维护。比如，老的项目中直接使用了 log4j，但 log4j 已经停止维护不再更新，现在想升级到 log4j2 后换成 logback，因 API 的不兼容所以替换的代价就高了。

3. 一个类中通常只使用一个 Logger 对象，Logger 应该是 private static final 的。

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

private static final Logger logger = LoggerFactory.getLogger(Demo.class);

4. 使用占位符，不要使用字符串拼接。

字符串拼接一方面不便于阅读，另一方面字符串的拼接会使用 StringBuilder 的 append()方式，有一定的性能损耗。使用占位符仅是替换动作，可以有效提升性能。

// 推荐
logger.info("用户 {} 借走图书 <<{}>> ",  userName, bookTitle);

// 不推荐
logger.info("用户 " + userName + " 借走图书 <<" + bookTitle + ">>");

5. 输出异常的全部信息，不要使用 logger.error(msg) 和 logger.error(msg,e.getMessage())，因为它们会丢失掉最重要的 StackTrace 信息。

void foo() {
    try {
        //  do something ...
    } catch ( Exception e ) {
        logger.error("Bad things : ", e); // 正确

        logger.error(e.getMessage());  // 错误
        logger.error("Bad things : ", e.getMessage()); // 错误
    }
}

6. catch 分支不要使用 System print（包括 System.out.println 和 System.error.println）和 printStackTrace 语句，代替 log 打印异常信息。

void foo() {
    try{
        // do something...
    } catch ( Exception e ) {
        logger.error("Bad things : ",e );  // 正确

        System.out.println(e.getMessage());  // 错误
        System.err.println(e.getMessage());  // 错误
        e.printStackTrace();  // 错误
    }
}

7. 出于性能的考虑，建议执行频率非常搞的核心代码中的 trace/debug 低级别的日志增加开关判断。

虽然日志框架内部有级别开关判断，比如 logger.debug(…) 在 Slf4j 内部调用的是 ExtendedLogger.logIfEnabled(String var1, Level var2 …)，但是参数可能会进行字符串拼接运算，此时直接在外层进行开关判断可以省去无畏的方法调用，以及可能的字符串拼接开销。

if (logger.isDebugEnabled ()) {
    logger.debug("return content:" + content);
}

8. 可用 warn 级别日志记录不在功能范围内的操作，或错误的请求参数等场景，避免用户投诉时不知所措。但此类场景不要使用 error 级别日志，避免不必要的告警。

9. 严格控制生产日志:

禁止输出 debug 日志，对于支持动态调整日志级别的，不要将打开 debug 及以下级别的开关；
有选择地输出 info 日志，避免打印大的对象，应该选择性的将关键的业务信息打印出来;
如果使用 warn 来记录刚上线时的业务行为信息，一定要注意日志输出量的问题，避免把服务器磁盘撑爆，并记得及时删除这些观察日志。

10. Logback / Log4j / Log4j2 中的 additivity 属性设为 false

通过 additivity 属性可以控制子 Logger 是否继承父 Logger 的 appender，Logback / Log4j / Log4j2 都支持该属性。属性 additivity 默认为 true 表示子 Logger 会继承父 Logger 的 appender，子 Logger 会在父 Logger 的 appender 里输出。将 additivity 设为 false，则子 Logger 只会在自己的 appender 里输出，可避免重复日志打印。

<!--Logback 中关闭 additivity-->
<Configuration>
  ...
  <Loggers>
    <Logger name="demo.wood" level="debug" additivity="false">
      <AppenderRef ref="applog" />
    </Logger>
    ...
  </Loggers>
</Configuration>

<!--Log4j2 中关闭 additivity-->
<Configuration>
    ...
    <Loggers>
        <Logger name="org.springframework" level="INFO" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        ...
    </Loggers>
</Configuration>

11. 谨慎打印日志

要明确不同日志的用途，对日志内容进行分类，比如框架日志和应用日志分离。
绝不要打印没用的日志，防止无用日志淹没重要信息；日志信息要精准，努力做到仅凭日志就可以定位问题。没有限制的日志输出，会带来无畏的性能和资源浪费，严重的会导致 OOM，应用直接崩溃。
查询类接口不要将查询出来的数据全部打印，存在 DB 中的数据，查询出来后再打印一遍意义不带还消耗资源。
写接口需要写日志，尽可能将有用的业务信息记录下来，但也要避免 controller、service 等多层重复打印。

12. 建议提供动态日志输出功能

动态日志输出可以实时调整系统日志级别，常见的做法是配置中心提供了服务的日志级别动态下发功能，在需要时实时调整（一般都要审批）日志级别以便获取重要信息。虽然不建议在生产中打开低级别的日志，但在遇到重大疑难问题时，可临时选择一个生产实例动态调低日志级别，以便问题排查。所以动态日志在实际中还是很有用的。关键动态日志的实现，可参考下节说明。

4. 动态日志输出

Log4j2 和 Logback 都支持在线动态修改日志级别，除了提供相应的 API，还提供了 JMX 支持。下面通过例子演示下两种使用方式，其中 logback 的版本为 1.2.3，log4j2 的版本为 2.13.3(不同版本的 API 可能有所不同，在使用前先去官方文档 double check 下)。

4.1. 通过 API 动态修改日志级别

Log4j2 和 Logback 都提供了修改日志级别的方法 setLevel，其中 Logback 的 setLevel 方法位于 classch.qos.logback.classic.Logger里， setLevel 方法，Log4j 的 setLevel 方法位于org.apache.logging.log4j.core.config.Configurator下。使用方式上都是先获取到需要设置的 logger，然后在对 logger 设置级别，下面的示例代码演示了两者 API 的使用方式。

// Example 1: 设置 Logback 日志级别
Logger logger = oggerContext.getLogger("需要设置级别的 logger 名");
logger.setLevel(Level.DEBUG);

// Example 2: 设置 Log4j2 日志级别
Logger logger4j = LogManager.getLogger("需要设置级别的 logger 名");
Configurator.setLevel(logger4j.getName(), Level.ERROR);

由于我们通常使用 SL4J 而不是直接使用具体的日志框架，因而在获取 logger 的过程中注意类型转换。下面通过 DynamicLogbackLevelDemo 演示下在 SLF4J + Logback 使用方式下，如何通过 API 动态修改日志级别。Log4j / Log4j2 的使用方式类似，这里不再演示。

Logback 配置文件

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}] -- [%-5p]: [%c] -- %m%n</pattern>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

Demo Code

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import com.google.common.collect.ImmutableMap;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.Map;
import java.util.Scanner;

public class DynamicLogbackLevelDemo {
    private static final Logger logger = LoggerFactory.getLogger(DynamicLogbackLevelDemo.class);

    private static final Map<Integer, String> LOG_LEVEL_MAP = new ImmutableMap.Builder<Integer, String>()
            .put(1, "TRACE").put(2, "DEBUG").put(3, "INFO").put(4, "WARN").put(5, "ERROR").build();

    public static void main(String[] args) throws Exception {
        Scanner scanner = new Scanner(System.in);
        String userInput = null;
        do {
            System.out.printf("\nPlease Enter Logback Logger Level (q to quit): 1 - TRACE, 2 - DEBUG, 3 - INFO, 4 - WARN, 5 - ERROR\n");

            userInput = scanner.nextLine().trim();
            if (!StringUtils.isNumeric(userInput)) {
                continue;
            }

            String logLevel = LOG_LEVEL_MAP.get(Integer.parseInt(userInput));
            if (null != logLevel) {

                // 获取 loggert
                LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
                ch.qos.logback.classic.Logger tmplogger = loggerContext.getLogger(DynamicLogbackLevelDemo.class);

                // 修改日志级别
                System.out.printf("[current logger level]: %s ---> [new logger level]: %s\n", tmplogger.getLevel(), logLevel);
                tmplogger.setLevel(Level.toLevel(logLevel));

                System.out.println("verifying new logger level:");
                logger.trace("sample trace log");
                logger.debug("sample debug log");
                logger.info("sample info log");
                logger.warn("sample warn log");
                logger.error("sample error log");
            }
        } while (!"q".equalsIgnoreCase(userInput));
        scanner.close();
    }
}

下图是运行 DynamicLogbackLevelDemo 后的截图，可以看到，随着用户输入不同的日志级别，logback 就会按级别进行日志过滤，并在控制台输出不同的日志信息。

4.2. 使用 JMX 动态修改日志级别

Log4j2 和 Logback 都支持 JMX 设置日志级别，其中 Log4j2 不需要配置默认就打开了 JMX 功能，而 Logback 需要在配置文件中添加 <jmxConfigurator /> 才能开启 JMX 功能。下面通过 DemoApp 演示下 Logback 的 JMX 功能，Log4j2 / Log4j 类似，这里不再赘述。

DemoApp 是在 spring initializr 网站 https://start.spring.io 上自动生成的一个应用，由于 springboot 默认使用 logback，因而 DemoApp 没有额外配置，只是增加了下面的 logback 配置文件。

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <!-- 开启 JMX -->
    <jmxConfigurator />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%logger{36}]: %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="fileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/demoApp.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>demoApp-%d-%i.log</fileNamePattern>
            <MaxHistory>20</MaxHistory>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>500MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] [%-5level] [%logger{36}]: %msg%n</pattern>
            <charset>UTF-8</charset>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
    </appender>

    <logger name="org.springframework" additivity="false">
        <level value="ERROR" />
        <appender-ref ref="STDOUT" />
        <appender-ref ref="fileAppender" />
    </logger>

    <logger name="org.apache.tomcat.util" additivity="false">
        <level value="ERROR"/>
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="fileAppender"/>
    </logger>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="fileAppender"/>
    </root>
</configuration>

启动 DemoApp 后，就可以验证 Logback JMX 的功能了。这里选择 jconsole 测试下 Logback 的动态日志输出功能。使用 jconsole 连接上 DemoApp 后，在左边的窗口找到 ch.qos.logback.classic 打开 operations 就可以看到 setLoggerLevel 操作，填上 logger 名称和日志级别后回车，就能及时修改日志级别。下图展示了在 jconsole 中将 org.springframework 包下的日志级别调整为 debug 后，控制台立即输出 debug 及以上级别的日志效果。

下面为使用 jconsole 动态调整 Log4j2 的截图，操作起来和 logback 类似。由于 Springboot 默认使用 logback，同时也提供了对 log4j2 的集成，因而在 springboot 项目中使用 log4j2 时需要在 pom 中排除spring-boot-starter-logging的依赖，同时添加spring-boot-starter-log4j2的依赖即可。