【Java日志】你真的知道怎么使用Java日志API吗？

一、背景

  在平时的开发过程中，常常看到一些编码不规范的打印日志的代码，这些代码虽然使用了日志API，却达不到预期的记录日志的目的，这正是我写本篇文章的背景原因。对于一些经验不足的开发人员来讲，他们可能会照猫画虎或者直接就使用日志API，只要代码不报错就行，往往不去理解API的含义，也没有系统学习底层原理。其实，我也是这样过来的。下面就从以下两个方面分享一些错误使用Java日志API的示例，一起学习避坑。

• 占位符的错误使用
• 异常日志的错误使用

二、Java日志API错误使用示例

1、占位符的错误使用示例

• 示例一：使用了占位符，却不给占位参数

// 使用了占位符，却对参数进行字符串拼接
Integer userId = 1001;
Long merchantId = 1000001234L;
// 输出结果为：创建订单请求参数：userId={}, merchantId={}10011000001234
log.info("创建订单请求参数：userId={}, merchantId={}" + userId + merchantId);
// 输出结果为：创建订单请求参数：userId={}1001, merchantId={}1000001234
log.info("创建订单请求参数：userId={}" + userId + ", merchantId={}" + merchantId);

// 使用了占位符，忘记给占位参数
// 输出结果即为原样输出
log.info("创建订单请求参数：userId={}, merchantId={}");
log.info("创建订单请求结果：orderId={}")

错误原因：以上代码实际使用到的是

/**
 * Log a message at the INFO level.
 *
 * @param msg the message string to be logged
 */
public void info(String msg);

而不是

/**
 * Log a message at the INFO level according to the specified format
 * and arguments.
 * <p/>
 * <p>This form avoids superfluous string concatenation when the logger
 * is disabled for the INFO level. However, this variant incurs the hidden
 * (and relatively small) cost of creating an <code>Object[]</code> before invoking the method,
 * even if this logger is disabled for INFO. The variants taking
 * {@link #info(String, Object) one} and {@link #info(String, Object, Object) two}
 * arguments exist solely in order to avoid this hidden cost.</p>
 *
 * @param format    the format string
 * @param arguments a list of 3 or more arguments
 */
public void info(String format, Object... arguments);

• 示例二：不使用占位符，却给占位参数

Integer userId = 1001;
Long merchantId = 1000001234L;
// 输出结果为：创建订单请求参数：userId=, merchantId=
// More arguments provided (2) than placeholders specified (0) 
log.info("创建订单请求参数：userId=, merchantId=", userId, merchantId);

// 输出结果为：创建订单请求参数：userId=1001, merchantId=
// More arguments provided (2) than placeholders specified (1) 
log.info("创建订单请求参数：userId={}, merchantId=", userId, merchantId);

不给占位符或占位符数量少于占位参数数量，这种情况多余的占位参数会不输出。

• 示例三：使用了占位符，占位参数数量与占位符数量不一致

Integer userId = 1001;
Long merchantId = 1000001234L;
// 输出结果为：创建订单请求参数：userId=1001, merchantId={}
// Fewer arguments provided (1) than placeholders specified (2)  
log.info("创建订单请求参数：userId={}, merchantId={}", userId);

Long orderId = 100110000004321L;
// 输出结果为：创建订单请求结果：userId=1001, merchantId=1000001234
// More arguments provided (3) than placeholders specified (2) 
log.info("创建订单请求结果：userId={}, merchantId={}", userId, merchantId, orderId);

占位参数比占位符少，则多余的占位符不被替换，原样输出；
占位参数比占位符多，则多余的占位参数不被输出。

• 正确示例：使用占位符，且占位参数数量与占位符数量保持一致

Integer userId = 1001;
Long merchantId = 1000001234L;
// 输出结果为：创建订单请求参数：userId=1001, merchantId=1000001234
log.info("创建订单请求参数：userId={}, merchantId={}", userId, merchantId);

Long orderId = 100110000004321L;
// 输出结果为：创建订单请求结果：userId=1001, merchantId=1000001234, orderId=100110000004321
log.info("创建订单请求结果：userId={}, merchantId={}, orderId={}", userId, merchantId, orderId);

2、异常日志的错误使用示例

• 示例一：仅输出异常信息，不输出异常堆栈

try {
   Long orderId = createOrder(userId, merchantId);
   int num = 666 / 0;
} catch (Exception e) {
    // 输出结果为：创建订单失败：user=1001, msg=/ by zero
    log.error("创建订单失败：user={}, msg={}", userId, e.getMessage());
}

这里不是说只输出异常信息就是一定不对的，只是不输出异常堆栈信息不便于排查与定位问题，建议尽量避免只输出异常信息。我曾经犯过这种错误，生产环境因为数据问题导致空指针异常，而异常信息中只能看到null，比如“创建订单失败：msg=null”。

• 示例二：输出异常堆栈，但却给占位符

try {
   Long orderId = createOrder(userId, merchantId);
   int num = 666 / 0;
} catch (Exception e) {
    /* 输出结果为：
        12:35:35.984 [main] ERROR stu.ljxcolin.logging.slf4j.Slf4jTests - 创建订单失败：user=1001, e={}
        java.lang.ArithmeticException: / by zero
            at stu.ljxcolin.logging.slf4j.Slf4jTests.test01(Slf4jTests.java:28)
            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
            at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
            at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
            at java.lang.reflect.Method.invoke(Method.java:498)
            at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) 
     */
    log.error("创建订单失败：user={}, e={}", userId, e);
}

• 正确示例：输出异常堆栈信息，且throwable不需要给占位符

try {
   Long orderId = createOrder(userId, merchantId);
   int num = 666 / 0;
} catch (Exception e) {
    /* 输出结果为：
        12:35:35.984 [main] ERROR stu.ljxcolin.logging.slf4j.Slf4jTests - 创建订单失败：user=1001
        java.lang.ArithmeticException: / by zero
            at stu.ljxcolin.logging.slf4j.Slf4jTests.test01(Slf4jTests.java:28)
            at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
            at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
            at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
            at java.lang.reflect.Method.invoke(Method.java:498)
            at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)  
     */
    log.error("创建订单失败：user={}", userId, e);
}

// 请参见以下两个API
// public void error(String format, Object... arguments);
// public void error(String msg, Throwable t);

好了，Java日志API错误使用示例就分享完了。在我们使用Java日志API时需谨记：（1）使用占位符时要给占位参数，且占位符的数量要与占位参数的数量保持一致。（2）输出异常堆栈信息时，throwable不需要给占位符，把throwable放在最后一个参数。

三、推荐一个学习Java日志的项目

  当然，只学习了如何正确使用日志API是不够的，下面介绍下我在学习各种日志框架过程中建立的一个Git仓库logging。该项目主要是对日志实现和日志门面进行了较全面的学习，包括日志的API、日志等级、日志格式以及日志配置文件的学习，还使用SpringBoot整合了Logback和Log4j2。大家可以参照该项目进行进一步的学习，也可以给该仓库提出建议或提交代码。仓库地址如下：
https://www.gitee.com/ljxcolin/logging.git。