Log4j2分析与实践-源码分析(一)

    在学会使用Log4j2之后,有必要继续研究其实现原理吗?这还真不好说,个人推荐尽可能深入地去理解它,因为当你在项目中,遇到诸如日志没有正常打印时,如果你对Log4j2有足够深入的理解,那么可能你会花更少的时间来排查问题。除此之外,深入地研究任何一款开源项目,学到的不仅仅是这个项目本身,还会学到很多设计思想,可以利用到日常工作中。

    没有下载Log4j2源代码的读者可以去这里下载:Log4j2源码

    通过之前的系列文章读者可以知道,在需要打印日志的地方,使用org.apache.logging.log4j.LogManager来获取一个Logger。比如需要在A类中打印日志,那么就需要在A类中通过LogManager.getLogger来获取Logger,若Logger是在A类中定义的一个静态常量:

private static final Logger LOGGER = LogManager.getLogger("loggerName");

    那么通过JVM加载机制可知,当A被加载并初始化时,LogManager也会被加载并初始化。本篇文章就会讲解LogManager的初始化过程。

当LogManager被初始化时,static{}块中的代码会执行,它的作用只有一个:初始化LoggerContextFactory。我们看看这段代码:

/**
 扫描classpath来找到所有指定的LoggerContextFactory实现
 */
static {
	// 可以通过设置log4j2.loggerContextFactory属性(即代码中的FACTORY_PROPERTY_NAME变量)来指定一个LoggerContextFactory实现。
	/**
	 会在classpath下查找log4j2.component.properties文件并解析配置的属性。
	 */
	final PropertiesUtil managerProps = PropertiesUtil.getProperties();
	/**
	 从属性配置中查找指定的LoggerContextFactory全路径名称,即log4j2.loggerContextFactory。
	 */
	final String factoryClassName = managerProps.getStringProperty(FACTORY_PROPERTY_NAME);
	if (factoryClassName != null) {
		try {
			/**
			根据factoryClassName实例化一个LoggerContextFactory。这里需要注意,如果在系统属性中配置
			 了log4j.ignoreTCL=true(即不使用线程上下文加载器),那么Log4j2会使用默认的加载器(即使用Class.forName方式)
			 来加载指定的Factory。若没有设置log4j.ignoreTCL,那么就会使用线程上下文加载器。后续的实例化中也会遇到类似的逻辑,
			 那么这个逻辑会对我们造成怎样的影响呢?如果同一个应用中,LogManager被不同的加载器先后加载后,会导致前一次实例化
			 的LoggerContextFactory会被后一次实例化的覆盖。也就会遇到<a href="https://www.sanesee.com/article/log4j2-async-logger-context-selector-cast-error" target="_blank">Log4j2异步Logger转换失败排查记录</a>问题。
			 */
			factory = LoaderUtil.newCheckedInstanceOf(factoryClassName, LoggerContextFactory.class);
		} catch (final ClassNotFoundException cnfe) {
			LOGGER.error("Unable to locate configured LoggerContextFactory {}", factoryClassName);
		} catch (final Exception ex) {
			LOGGER.error("Unable to create configured LoggerContextFactory {}", factoryClassName, ex);
		}
	}
	if (factory == null) {
		final SortedMap&lt;Integer, LoggerContextFactory&gt; factories = new TreeMap&lt;&gt;();
		// 在OSGI环境中,下面对ProviderUtil的调用会阻塞,直到Provider被准备好。
		if (ProviderUtil.hasProviders()) {
			/**
			 当用户没有指定LoggerContextFactory时,就会查找classpath下的所有META-INF/log4j-provider.properties文件,
			 并使用其配置实例化Factory。log4j-provider.properties中定义了需要使用的Factory信息,
			 比如log4j-core/src/main/resources/META-INF/log4j-provider.properties的内容如下:
			 LoggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactory
			 Log4jAPIVersion = 2.6.0
			 FactoryPriority= 10
			 它指定的Factory为org.apache.logging.log4j.core.impl.Log4jContextFactory,api的版本为2.6.0,优先级为10。
			 数字越大,优先级越高。
			 */
			for (final Provider provider : ProviderUtil.getProviders()) {
				/**
				 加载log4j-provider.properties指定的Factory。
				 */
				final Class&lt;? extends LoggerContextFactory&gt; factoryClass = provider.loadLoggerContextFactory();
				if (factoryClass != null) {
					try {
						/**
						 将加载的Factory放到优先级Map factories中。
						 */
						factories.put(provider.getPriority(), factoryClass.newInstance());
					} catch (final Exception e) {
						LOGGER.error("Unable to create class {} specified in {}", factoryClass.getName(), provider
								.getUrl().toString(), e);
					}
				}
			}
			if (factories.isEmpty()) {
				LOGGER.error("Log4j2 could not find a logging implementation. "
						+ "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");
				/**
				 当没有找到Factory时(通常是由于log4j-core.jar没有加到classpath中),
				 使用默认的Factory SimpleLoggerContextFactory。
				 */
				factory = new SimpleLoggerContextFactory();
			} else if (factories.size() == 1) {
				/**
				 当只有一个Factory时,直接使用这个Factory。
				 */
				factory = factories.get(factories.lastKey());
			} else {
				final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n");
				for (final Map.Entry&lt;Integer, LoggerContextFactory&gt; entry : factories.entrySet()) {
					sb.append("Factory: ").append(entry.getValue().getClass().getName());
					sb.append(", Weighting: ").append(entry.getKey()).append('\n');
				}
				/**
				 当找到的Factory超过1个时,使用优先级最高的Factory。
				 */
				factory = factories.get(factories.lastKey());
				sb.append("Using factory: ").append(factory.getClass().getName());
				LOGGER.warn(sb.toString());
			}
		} else {
			LOGGER.error("Log4j2 could not find a logging implementation. "
					+ "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");
			factory = new SimpleLoggerContextFactory();
		}
	}
}

本文由SANESEE.COM合作作者原创或翻译,转载需注明出处

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))的语句表示将两个来自不同加载器的实例进行转换,所以会报错。

本文由SANESEE.COM合作作者原创或翻译,转载需注明出处

Log4j2分析与实践-常用组件

Commons Logging Bridge

    Commons Logging Bridge使得使用Commons Logging API的应用可以使用Log4j2的实现。
    它的使用很简单,只需要将bridge的jar包、其它Log4j2的jar包和Commons Logging的jar包都放到classpath下,那么所有使用Commons Logging API的日志请求会被路由到Log4j2.

Log4j 1.2 Bridge

    Log4j 1.2 Bridge使得使用Log4j 1.2 API的应用可以使用Log4j2。
    要使用Log4j 1.2 Bridge的话,只需要移除所有Log4j 1.x的jar包,然后加入bridge的jar包。配置好之后,所有使用Log4j 1.x API的日志请求都会路由到Log4j 2。然而,如果应用会尝试修改旧版的Log4j,比如添加Appender和Filter等,就可能会遭遇失败,因为有些方法可能已经不存在了。

Log4j 2 SLF4J绑定

    Log4j 2 SLF4J绑定使得使用SLF4J API的应用可以使用Log4j2的实现。
    SLF4J绑定会将所有的SLF4J API路由到Log4j2。仅需要将SLF4J绑定的jar包、Log4j2的jar包和SLF4J API的jar包添加到classpath下就可以了。

Log4j to SLF4J适配器

    Log4j to SLF4J适配器与Log4j 2 SLF4J绑定是不同的,Log4j 2 SLF4J绑定是将调用SLF4J API的日志请求路由到Log4j2的实现上,而Log4j to SLF4J适配器是将调用Log4j2 API的日志请求路由到SLF4J。使用这种适配器是有性能损失的,因为Log4j2的消息必须要格式化之后才能传递给SLF4J。

    需要将Log4j to SLF4J Adapter的jar包、Log4j2 API的jar包和SLF4J API的jar包放到classpath下。

    注意:不要同时使用Log4j2 SLF4J绑定(log4j-slf4j-impl-2.0.jar)和SLF4J适配器(log4j-to-slf4j-2.0.jar),因为它会导致事件无止尽地在SLF4J和Log4j2之间路由。

本文由SANESEE.COM合作作者原创或翻译,转载需注明出处