log4j2 -- 打印异常日志

背景

在工程中，我们会遇到catch Exception的情况，如下所示：

try{
    //some codes
}catch(Exception e){
    //do something
}

这时，我们不希望异常信息被吞掉，因此会把异常堆栈输出到日志。

经常与log4j2使用的是slf4j框架。而常用的slf4j框架打印错误的日志api有：

    public void error(String msg);
    public void error(String format, Object arg);
    public void error(String format, Object arg1, Object arg2);
    public void error(String format, Object... arguments);
    public void error(String msg, Throwable t);

乍一看，貌似只有public void error(String msg, Throwable t)这个api能打印异常日志。

但是，经常在一些代码中，看到这样的代码，照样可以打印异常日志：

try{
    //some codes
}catch(Exception e){
    logger.error("fatal exception, a={}, b={}", a, b, e)
}

这是如何做到的？

原理分析

要想查看原因，需要从源码着手。
首先，很明显

logger.error("fatal exception, a={}, b={}", a, b, e)
调用的是
public void error(String format, Object... arguments);
这个方法

那么，我们循着public void error(String format, Object... arguments)这个方法的实现来分析。

首先，这个方法是slf4j-api.jar中的接口方法：

//slf4j-api.jar
public interface Logger {
    public void error(String format, Object... arguments);
}

其实现是在log4j-slf4j-impl.jar中

//log4j-slf4j-impl.jar
public class Log4jLogger implements LocationAwareLogger, Serializable {
    @Override
    public void error(final String format, final Object... args) {
        logger.logIfEnabled(FQCN, Level.ERROR, null, format, args);
    }
}

然后继续跟，就到了log4j-api.jar中。中间有很多步骤略过了，因为都不是关键的。直到发现了这个方法

//log4j-api.jar
public abstract class AbstractLogger implements ExtendedLogger, Serializable {
        protected void logMessage(String fqcn, Level level, Marker marker, String message, Object... params) {
            Message msg = this.messageFactory.newMessage(message, params);
            this.logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
        }
}

之所以对这个方法敏感，是因为，本来参数中没有指明是否存在Throwable类型，但是凭空出现了msg.getThrowable()这个方法。所以，可以猜测，这里一定有跟异常信息处理有关的逻辑。(PS: 这里也说明，一个通俗易懂的方法名是多么的重要！！！)

既然getThrowable()是Message类的一个方法，那么下一步就是要分析this.messageFactory.newMessage(message, params)了。

newMessage()是messageFactory的方法。而messageFactory是在AbstractLogger的构造函数中赋值的：

public AbstractLogger(String name) {
   this(name, createDefaultMessageFactory());
}

public AbstractLogger(String name, MessageFactory messageFactory) {
    this.name = name;
    this.messageFactory = messageFactory == null?createDefaultMessageFactory():narrow(messageFactory);
    this.flowMessageFactory = createDefaultFlowMessageFactory();
}

messageFactory是由createDefaultMessageFactory()构造的：

private static MessageFactory2 createDefaultMessageFactory() {
    try {
        final MessageFactory result = DEFAULT_MESSAGE_FACTORY_CLASS.newInstance();
        return narrow(result);
    } catch (final InstantiationException | IllegalAccessException e) {
        throw new IllegalStateException(e);
    }
}

发现，MessageFactory是通过反射获取的DEFAULT_MESSAGE_FACTORY_CLASS的一个实例。

DEFAULT_MESSAGE_FACTORY_CLASS是怎么来的？

 public static final Class<? extends MessageFactory> DEFAULT_MESSAGE_FACTORY_CLASS =
            createClassForProperty("log4j2.messageFactory", ReusableMessageFactory.class,
                    ParameterizedMessageFactory.class);

再看createClassForProperty()方法的实现：

private static Class<? extends MessageFactory> createClassForProperty(final String property,
            final Class<ReusableMessageFactory> reusableParameterizedMessageFactoryClass,
            final Class<ParameterizedMessageFactory> parameterizedMessageFactoryClass) {
    try {
        final String fallback = Constants.ENABLE_THREADLOCALS ? reusableParameterizedMessageFactoryClass.getName()
                : parameterizedMessageFactoryClass.getName();
        final String clsName = PropertiesUtil.getProperties().getStringProperty(property, fallback);
        return LoaderUtil.loadClass(clsName).asSubclass(MessageFactory.class);
    } catch (final Throwable t) {
        return parameterizedMessageFactoryClass;
    }
}

看到这里，就清楚了：
如果log4j2.messageFactory属性没有配置，则MessageFactory的实例是ParameterizedMessageFactory

ParameterizedMessageFactory的newMessage方法如下所示：

public final class ParameterizedMessageFactory extends AbstractMessageFactory {
    @Override
    public Message newMessage(final String message, final Object... params) {
        return new ParameterizedMessage(message, params);
    }
}

ParameterizedMessage的构造函数如下：

public class ParameterizedMessage implements Message, StringBuilderFormattable {
    public ParameterizedMessage(final String messagePattern, final Object... arguments) {
        this.argArray = arguments;
        init(messagePattern);
    }
}

关键在于init()方法

private void init(final String messagePattern) {
    this.messagePattern = messagePattern;
    final int len = Math.max(1, messagePattern == null ? 0 : messagePattern.length() >> 1); // divide by 2
    this.indices = new int[len]; // LOG4J2-1542 ensure non-zero array length
    final int placeholders = ParameterFormatter.countArgumentPlaceholders2(messagePattern, indices);
    initThrowable(argArray, placeholders);
    this.usedCount = Math.min(placeholders, argArray == null ? 0 : argArray.length);
}

private void initThrowable(final Object[] params, final int usedParams) {
    if (params != null) {
        final int argCount = params.length;
        if (usedParams < argCount && this.throwable == null && params[argCount - 1] instanceof Throwable) {
            this.throwable = (Throwable) params[argCount - 1];
        }
    }
}

主要关注initThrowable()方法。看到这里，就真相大白了：

• 首先会计数传入的messagePattern中占位符的数量，假设为N。(亦即usedParams参数)
• 如果可变参数列表中，参数的数量大于N，并且最后一个参数是Throwable类型的，那么则打印异常信息。
• MessageFactory需要是ParameterizedMessageFactory或者ParameterizedNoReferenceMessageFactory类型

参考

• log4j2源码