Cycle in LogAdapter.Log4jLog initialization within log appender

[garyrussell]

Affects: 5.2.x

The Spring implementation of commons-logging has the following logic within the LogAdapter for Log4j2...

		private static final LoggerContext loggerContext =
				LogManager.getContext(Log4jLog.class.getClassLoader(), false);

...

		public Log4jLog(String name) {
			this.logger = loggerContext.getLogger(name);
		}

If a custom appender depends on a class that has a static logger defined, we get an NPE on the loggerContext because the constructor is called before the static field is initialized.

For the full context of the issue, see spring-projects/spring-amqp-samples#59 and spring-projects/spring-amqp#1148. The work-around was to defer initialization of the classes with the static loggers until the log system is initialized.

This may be an unsolvable catch-22 but I thought I should at least raise the issue in case the Spring Team has ideas. This was not an issue with Boot 1.5/Spring 4.3.

Here is a simple example that exhibits the behavior:

@SpringBootApplication
public class Rgh1148Application {

	public static void main(String[] args) {
		SpringApplication.run(Rgh1148Application.class, args);
	}

}

@Plugin(name = "Test", category = "Core", elementType = "appender", printObject = true)
public class MyAppender extends AbstractAppender {

	private final SomeClass someClass = new SomeClass();

	public MyAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions,
			Property[] properties) {
		super(name, filter, layout, ignoreExceptions, properties);
	}

	@PluginFactory
	public static MyAppender create(
			@PluginConfiguration final Configuration configuration,
			@PluginAttribute("name") String name,
			@PluginElement("Layout") Layout<? extends Serializable> layout,
			@PluginElement("Filter") Filter filter,
			@PluginAttribute("ignoreExceptions") boolean ignoreExceptions) {
		return new MyAppender(name, filter, layout, ignoreExceptions, null);
	}

	@Override
	public void append(LogEvent event) {
		this.someClass.foo(event);
	}

}

class SomeClass {

	private static final Log logger = LogFactory.getLog(SomeClass.class);

	public void foo(LogEvent event) {
		logger.info(event);
	}

}

<?xml version="1.0" encoding="UTF-8"?>
<Configuration packages="com.example.demo">
	<Appenders>
		<Console name="STDOUT" target="SYSTEM_OUT">
			<PatternLayout pattern="%m%n" />
		</Console>
		<Test name="myAppender">
		</Test>
	</Appenders>
	<Loggers>
		<Root>
			<AppenderRef ref="STDOUT, myAppender" />
		</Root>
	</Loggers>
</Configuration>

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
	<parent>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-parent</artifactId>
		<version>2.2.4.RELEASE</version>
		<relativePath/> <!-- lookup parent from repository -->
	</parent>
	<groupId>com.example</groupId>
	<artifactId>rgh1148</artifactId>
	<version>0.0.1-SNAPSHOT</version>
	<name>rgh1148</name>
	<description>Demo project for Spring Boot</description>

	<properties>
		<java.version>1.8</java.version>
	</properties>

	<dependencies>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter</artifactId>
			<exclusions>
				<exclusion>
					<groupId>org.springframework.boot</groupId>
					<artifactId>spring-boot-starter-logging</artifactId>
				</exclusion>
			</exclusions>
		</dependency>

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-log4j2</artifactId>
		</dependency>

		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-test</artifactId>
			<scope>test</scope>
			<exclusions>
				<exclusion>
					<groupId>org.junit.vintage</groupId>
					<artifactId>junit-vintage-engine</artifactId>
				</exclusion>
			</exclusions>
		</dependency>
	</dependencies>

	<build>
		<plugins>
			<plugin>
				<groupId>org.springframework.boot</groupId>
				<artifactId>spring-boot-maven-plugin</artifactId>
			</plugin>
		</plugins>
	</build>

</project>

2020-01-27 15:02:40,570 main ERROR Unable to invoke factory method in class com.example.demo.MyAppender for element Test: java.lang.ExceptionInInitializerError java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:1002)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:942)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:934)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:552)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:241)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:579)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:651)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:668)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:253)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194)
	at org.apache.commons.logging.LogAdapter$Log4jLog.<clinit>(LogAdapter.java:155) <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
	at org.apache.commons.logging.LogAdapter$Log4jAdapter.createLog(LogAdapter.java:122)
	at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:89)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
	at org.springframework.boot.SpringApplication.<clinit>(SpringApplication.java:196)
	at com.example.demo.Rgh1148Application.main(Rgh1148Application.java:10)
Caused by: java.lang.ExceptionInInitializerError
	at com.example.demo.MyAppender.<init>(MyAppender.java:38)
	at com.example.demo.MyAppender.create(MyAppender.java:52)
	... 25 more
Caused by: java.lang.NullPointerException
	at org.apache.commons.logging.LogAdapter$Log4jLog.<init>(LogAdapter.java:160) . <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
	at org.apache.commons.logging.LogAdapter$Log4jAdapter.createLog(LogAdapter.java:122)
	at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:89)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
	at com.example.demo.SomeClass.<clinit>(MyAppender.java:64)
	... 27 more

[jhoeller]

Since Log4J seems to be internally capable of retrieving the LoggerContext even in circular scenarios, we could simply move the LogManager.getContext to the constructor as well - so that it is being reliably called before our LoggerContext.getLogger invocation. In order to retain our current context caching, we could also have a mixed scenario where we're lazily initializing the context in a volatile field.

[jhoeller]

With even less impact, it seems we can keep initializing our static field and simply let the constructor perform a local LogManager.getContext call if the field happens to be not initialized yet.