slf4j的log.warn()的参数问题研究-阿里云开发者社区

一、背景

今天我们探讨一下@Slf4j的log.warn()的参数问题。

二、上源码

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

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 test0() {
        log.warn("code={},msg={}", 200, "成功！");
    }

参数指 200（第一个参数，对应第一个占位符），第二个参数“成功！”对应第二个占位符。

输出日志时拼接在一起：code=200,msg=成功

输出结果为：

00:05:46.731 [main] WARN com.chujianyun.common.log.WarnLogTest - code=200,msg=成功！

和设想的一样（前面是自动追加的可以定制）。

这个占位符和参数和String.format()函数非常相似

public static String format(String format, Object... args) {
        return new Formatter().format(format, args).toString();
    }

前面是格式化字符串，后面是对应占位符的参数。

等价于以下代码（我们可以对比学习）：

String.format("code=%d,msg=%s", 200, "成功！");

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

@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)来实现打印。

public void log(String FQCN, Priority p, Object msg, Throwable t) {
        int levelInt = this.priorityToLevelInt(p);
        this.differentiatedLog((Marker)null, FQCN, levelInt, msg, t);
    }