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 https://github.com/spring-projects/spring-amqp-samples/issues/59 and https://github.com/spring-projects/spring-amqp/issues/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
Comment From: 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.
Comment From: 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.