Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sample log4j2 doesn't work with spring-boot >=2.0.0.RELEASE #59

Closed
yejianfengblue opened this issue Jan 26, 2020 · 1 comment
Closed
Assignees

Comments

@yejianfengblue
Copy link

yejianfengblue commented Jan 26, 2020

Reproduce steps:

  1. Start latest windows RabbitMQ on localhost:5672

  2. checkout master branch from this project spring-amqp-samples

  3. Go to module log4j2. You can see the spring-boot version should be 2.2.2.RELEASE in log4j2/pom.xml

  4. Run module log4j2. get error log from stdout

main ERROR Appenders contains an invalid element or attribute "RabbitMQ"
main ERROR Unable to locate appender "rabbitmq" for logger config "org.springframework.amqp.samples.log4j2"

  1. Delete exchange log4j2Sample from RabbitMQ management UI, because default value of durable in annotation org.springframework.amqp.rabbit.annotation.Exchange are different between different spring-rabbit version.

  2. Change spring-boot-starter-parent version in log4j2/pom.xml to 1.5.x.RELEASE (I tested 1.5.3, 1.5.10, 1.5.22), run module log4j2, sample works and you can see log

Log via AmqpAppender: Sun Jan 26 11:08:21 CST 2020
Logs over Log4J AmqpAppender: Log via AmqpAppender: Sun Jan 26 11:08:21 CST 2020

  1. Delete exchange log4j2Sample from RabbitMQ management UI, because default value of durable in annotation org.springframework.amqp.rabbit.annotation.Exchange are different between different spring-rabbit version.

  2. Change spring-boot-starter-parent version in log4j2/pom.xml to 2.0.0.RELEASE, run module log4j2, get error log

2020-01-26 11:10:31,034 main ERROR Unable to invoke factory method in class org.springframework.amqp.rabbit.log4j2.AmqpAppender for element RabbitMQ: 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:958)
at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:898)
at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:890)
at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:513)
at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:237)
at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:249)
at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:545)
at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:617)
at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:634)
at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:229)
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.LogFactory$Log4jLog.(LogFactory.java:199)
at org.apache.commons.logging.LogFactory$Log4jDelegate.createLog(LogFactory.java:166)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:109)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:99)
at org.springframework.amqp.samples.log4j2.SpringBootAmqpAppenderApplication.(SpringBootAmqpAppenderApplication.java:43)
Caused by: java.lang.ExceptionInInitializerError
at org.springframework.expression.spel.SpelParserConfiguration.(SpelParserConfiguration.java:36)
at org.springframework.expression.spel.standard.SpelExpressionParser.(SpelExpressionParser.java:42)
at org.springframework.amqp.rabbit.core.RabbitTemplate.(RabbitTemplate.java:156)
at org.springframework.amqp.rabbit.log4j2.AmqpAppender.(AmqpAppender.java:120)
at org.springframework.amqp.rabbit.log4j2.AmqpAppender.createAppender(AmqpAppender.java:229)
... 23 more
Caused by: java.lang.NullPointerException
at org.apache.commons.logging.LogFactory$Log4jLog.(LogFactory.java:204)
at org.apache.commons.logging.LogFactory$Log4jDelegate.createLog(LogFactory.java:166)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:109)
at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:99)
at org.springframework.core.SpringProperties.(SpringProperties.java:53)
... 28 more
2020-01-26 11:10:31,038 main ERROR Null object returned for RabbitMQ in Appenders.
2020-01-26 11:10:31,043 main ERROR Unable to locate appender "rabbitmq" for logger config "org.springframework.amqp.samples.log4j2"
Exception in thread "main" java.lang.NoSuchMethodError: org.springframework.boot.SpringApplication.run(Ljava/lang/Object;[Ljava/lang/String;)Lorg/springframework/context/ConfigurableApplicationContext;
at org.springframework.amqp.samples.log4j2.SpringBootAmqpAppenderApplication.main(SpringBootAmqpAppenderApplication.java:46)
Process finished with exit code 1

@garyrussell garyrussell self-assigned this Jan 27, 2020
@garyrussell
Copy link
Contributor

Problem is due to a circular reference to LogAdapter$Log4jLog in the Spring implementation of commons-logging.

The CTOR is called from the appender while initializing the RabbitTemplate and before the loggerContext static has been assigned.

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

		private final ExtendedLogger logger;

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

Screen Shot 2020-01-27 at 12 12 24 PM

We need to defer initializing the RabbitTemplate until later.

garyrussell added a commit to garyrussell/spring-amqp that referenced this issue Jan 27, 2020
Resolves spring-projects/spring-amqp-samples#59

Defer creation of all Spring static loggers from appender until the
appender is initialized.

The first logger (e.g. Spring Boot) intializes the static `LoggerContext`
field in `LogAdapter.Log4jLog`; this, in turn initializes the appender.

However, the appender references Spring objects that have static loggers.
This causes the `Log4jLog` CTOR to be called before the field is initialized,
causing an NPE.

Defer creation of all static loggers until the appender is fully initialized.

Tested with the log4j2 sample app.
garyrussell added a commit to garyrussell/spring-amqp that referenced this issue Jan 27, 2020
Resolves spring-projects/spring-amqp-samples#59

Defer creation of all Spring static loggers from appender until the
appender is initialized.

The first logger (e.g. Spring Boot) intializes the static `LoggerContext`
field in `LogAdapter.Log4jLog`; this, in turn initializes the appender.

However, the appender references Spring objects that have static loggers.
This causes the `Log4jLog` CTOR to be called before the field is initialized,
causing an NPE.

Defer creation of all static loggers until the appender is fully initialized.

Tested with the log4j2 sample app.

**cherry-pick to 2.1.x**
garyrussell added a commit to garyrussell/spring-amqp that referenced this issue Jan 27, 2020
Resolves spring-projects/spring-amqp-samples#59

Defer creation of all Spring static loggers from appender until the
appender is initialized.

The first logger (e.g. Spring Boot) initializes the static `LoggerContext`
field in `LogAdapter.Log4jLog`; this, in turn initializes the appender.

However, the appender references Spring objects that have static loggers.
This causes the `Log4jLog` CTOR to be called before the field is initialized,
causing an NPE.

Defer creation of all static loggers until the appender is fully initialized.

Tested with the log4j2 sample app.

Also add a test for async sends.

**cherry-pick to 2.1.x**
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants