Log4j2异步Logger转换失败排查记录

    最近在使用Log4j2的系统上引入了淘宝的开源规则引擎qlExpress,后来突然Log42报出了以下错误(敏感内容已删除):

ERROR StatusLogger Unable to create custom ContextSelector. Falling back to default.
java.lang.ClassCastException: Cannot cast org.apache.logging.log4j.core.async.AsyncLoggerContextSelector to org.apache.logging.log4j.core.selector.ContextSelector
at java.lang.Class.cast(Class.java:3369)
at org.apache.logging.log4j.util.LoaderUtil.newCheckedInstanceOf(LoaderUtil.java:201)
at org.apache.logging.log4j.util.LoaderUtil.newCheckedInstanceOfProperty(LoaderUtil.java:226)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.createContextSelector(Log4jContextFactory.java:97)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.<init>(Log4jContextFactory.java:58)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at java.lang.Class.newInstance(Class.java:442)
at org.apache.logging.log4j.LogManager.<clinit>(LogManager.java:94)
at xxx.xxx.xxx.QLExpressManager.<clinit>(ExpressManager.java:22)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:264)
...
    根据提示可知,创建自定义的ContextSelector失败,详细信息显示不能将AsyncLoggerContextSelector转换为ContextSelector。
    但是在这个异常日志的前面已经有正常的日志打印出来。且将配置文件Configuration元素的status属性设置为trace,可以在控制台看到AsyncLoggerContextSelector已经正常配置:
TRACE Reregistering MBeans after reconfigure. Selector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector@49d19c65
    在这里就可以确定,AsyncLoggerContextSelector已经正常加载。那为什么程序还在试图去加载AsyncLoggerContextSelector?
    请看异常栈中的xxx.xxx.xxx.QLExpressManager,QLExpressManager中有个static代码块,并且有个logger的获取操作,代码如下:
private static final Logger LOGGER = LogManager.getLogger(ExpressManager.class);
static {
	try {
		runner.addFunctionOfClassMethod("methodXXX", QLExpressManager.class.getName(), "methodXXX",
				new String[] { "String", "String" }, null);
	} catch (Exception e) {
		...
	}
}
    在程序中首次调用QLExpressManager时,就会使用框架的类加载器对其进行加载;进入runner.addFunctionOfClassMethod源代码,就会发现qlExpress会再次使用Class.forName的方式去加载QLExpressManager这个类(使用sun默认加载器)。相当于QLExpressManager被两个不同的加载器各加载了一次。
    现在就很清晰了,QLExpressManager第二次被加载时,LogManager.getLogger的一系列相关的类也都会使用默认加载器进行加载,而这一些列类都会被两种加载器各加载一次。理论上,也不该报这种错,那么继续根据异常堆栈来排查。
    顺着异常堆栈来到org.apache.logging.log4j.util.LoaderUtil.newCheckedInstanceOf可见到以下代码:


public static <T> T newCheckedInstanceOf(final String className, final Class<T> clazz)
		throws ClassNotFoundException, NoSuchMethodException, InvocationTargetException, InstantiationException,
		IllegalAccessException {
	return clazz.cast(newInstanceOf(className));
}
    可以看到,程序试图将newInstanceOf(className)这个对象转换为clazz对应的对象类型。在这个return语句打断点发现clazz的classLoader是默认的加载器,而newInstanceOf(className)代码中却使用了以下代码去获取一个Class实例:



public static Class<?> loadClass(final String className) throws ClassNotFoundException {
	if (isIgnoreTccl()) {
		return Class.forName(className);
	}
	try {
		return getThreadContextClassLoader().loadClass(className); //程序会执行到这里
	} catch (final Throwable ignored) {
		return Class.forName(className);
	}
}
    getThreadContextClassLoader()会取到线程上下文的加载器,也就是框架的加载器。因此,前文clazz.cast(newInstanceOf(className))的语句表示将两个来自不同加载器的实例进行转换,所以会报错。