slf4j的log.warn()的使用问题解析

一、背景

今天我们探讨一下@Slf4j的org.slf4j.Logger#warn(java.lang.String, java.lang.Object...)的使用问题。

二、上源码

我先给出下面的几个测试用例，大家想想分别会输出什么？

import com.alibaba.fastjson.JSON;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.exception.ExceptionUtils;
import org.junit.Test;

@Slf4j
public class WarnLogTest {

    @Test
    public void test1() {

        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "呜呜，某某业务出错了！", "肿么办？");
        }
    }

    @Test
    public void test2() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "呜呜，某某业务出错了！", JSON.toJSONString(e));
        }
    }

    @Test
    public void test3() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={},e={}",
                    500, "呜呜，某某业务出错了！", ExceptionUtils.getStackTrace(e));
        }
    }

    @Test
    public void test4() {
        try {
            mockException();
        } catch (Exception e) {
            log.warn("code={},msg={}",
                    500, "呜呜，某某业务出错了！", e);
        }
    }

    private void mockException() {
        throw new RuntimeException("某个运行时异常");
    }
}

想好之后看看和我的分析是一样还是有出入。

三、分步解析

我们先看下warn的源码

 /**
     * Log a message at the WARN level according to the specified format
     * and arguments.
     * <p/>
     * <p>This form avoids superfluous string concatenation when the logger
     * is disabled for the WARN 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 WARN. The variants taking
     * {@link #warn(String, Object) one} and {@link #warn(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 warn(String format, Object... arguments);

发现前面是format格式化字符串，后面是对应的参数。

因此看第一个，根据上面的参数我们可以推测到，前面的{}是占位符，有两个，后面参数有三个，应该最后一个不显示

@Test
public void test1() {

    try {
        mockException();
    } catch (Exception e) {
        log.warn("code={},msg={}",
                500, "呜呜，某某业务出错了！", "肿么办？");
    }
}

运行结果：

23:37:18.525 [main] WARN com.chujianyun.common.log.WarnLogTest - code=500,msg=呜呜，某某业务出错了！

果然和我们想的一样！！

我们看第二个：

@Test
public void test2() {
    try {
        mockException();
    } catch (Exception e) {
        log.warn("code={},msg={},e={}",
                500, "呜呜，某某业务出错了！", JSON.toJSONString(e));
    }
}

根据上面的理论，三个占位符，三个参数应该没问题。

虽然和我们想的一样，但是打印的太不优雅了，好长而且都在一行里！！！

那我们换一个写法，采用工具类美化一下：

@Test
public void test3() {
    try {
        mockException();
    } catch (Exception e) {
        log.warn("code={},msg={},e={}",
                500, "呜呜，某某业务出错了！", ExceptionUtils.getStackTrace(e));
    }
}

效果还不错：

我们再看另外一个写法：

 @Test
public void test4() {
    try {
        mockException();
    } catch (Exception e) {
        log.warn("code={},msg={}",
                500, "呜呜，某某业务出错了！", e);
    }
}

根据前面的经验，我们认为这个应该不会打印e，因为格式化占位符只有两个，这个是三个参数。

我们发现结果和我们想的不一样！！！

四、探究

它是一个接口，我们看看他的实现类

我们以Log4JLoggerAdapter为例吧，看名字就知道是适配器模式。

适配器模式的目的：将一个类的接口转换成客户希望的另外一个接口。

适配器模式使得原本由于接口不兼容而不能一起工作的那些类可以一起工作。

如果想仔细研究可以看文末的参考资料。

我们继续，发现实现的代码在这里（这里是适配的函数）：

org.slf4j.impl.Log4jLoggerAdapter#warn(java.lang.String, java.lang.Object...)

 public void warn(String format, Object... argArray) {
    if (this.logger.isEnabledFor(Level.WARN)) {
        FormattingTuple ft = MessageFormatter.arrayFormat(format, argArray);
        this.logger.log(FQCN, Level.WARN, ft.getMessage(), ft.getThrowable());
    }

}

上半部分调用了这里：

final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray) {
    Throwable throwableCandidate = getThrowableCandidate(argArray);
    Object[] args = argArray;
    if (throwableCandidate != null) {
        args = trimmedCopy(argArray);
    }
    return arrayFormat(messagePattern, args, throwableCandidate);
}

然后调用到了这里

static final Throwable getThrowableCandidate(Object[] argArray) {
    if (argArray == null || argArray.length == 0) {
        return null;
    }

    final Object lastEntry = argArray[argArray.length - 1];
    if (lastEntry instanceof Throwable) {
        return (Throwable) lastEntry;
    }
    return null;
}

和这里

  private static Object[] trimmedCopy(Object[] argArray) {
    if (argArray == null || argArray.length == 0) {
        throw new IllegalStateException("non-sensical empty or null argument array");
    }
    final int trimemdLen = argArray.length - 1;
    Object[] trimmed = new Object[trimemdLen];
    System.arraycopy(argArray, 0, trimmed, 0, trimemdLen);
    return trimmed;
}

真相就浮现了！

getThrowableCandidate函数会判断数组最后一个是不是Throwable的子类型，如果是转成Throwable返回给前面，否则返回null.

而trimmedCopy(Object[] argArray)函数只复制了参数长度-1个长度，忽略最后一个元素。

最终调用org.slf4j.helpers.MessageFormatter#arrayFormat(java.lang.String, java.lang.Object[], java.lang.Throwable)去构造打印对象FormattingTuple。

然后调用log4j的

org.apache.log4j.Category#log(java.lang.String, org.apache.log4j.Priority, java.lang.Object, java.lang.Throwable)来实现打印。

// See also http://jira.qos.ch/browse/SLF4J-159
public void log(String FQCN, Priority p, Object msg, Throwable t) {
    int levelInt = priorityToLevelInt(p);
    differentiatedLog(null, FQCN, levelInt, msg, t);
}

另外我们还可以打断点验证一下（具体自己可单步跟下去）。

另外特别提示，善用左下角的调用栈，可以看到整个调用链路，双击可以切到上层源码

因此结论是：

使用org.slf4j.Logger#warn(java.lang.String, java.lang.Object...)时，最后一个参数如果是异常可自动追加到日志中。

这得益于适配器模式，底层实现提供了这种兼容。

五、总结

一、遇到和自己预期不符的代码，一定要借机研究一下，能够学到更多。可能发现自己没注意的点，没掌握好的点，也可能会发现一个隐患或者BUG。

二、遇到问题尽量跟到源码里，从源码角度去分析为什么，是快速成长的一个途径。

三、验证代码是否运行，可以断点，这是一个经验。

附录：

适配器模式  https://www.runoob.com/design-pattern/adapter-pattern.html