Log4j2LoggingSystem pollutes Log4j2's environment with a SpringEnvironmentPropertySource that is never removed

[rlratcliffe]

It appears that reloading of route changes made in a project using spring-boot-devtools is no longer working with Camel 4 and Spring Boot 3. It was previously working with these versions:

    <spring-boot.version>2.7.18</spring-boot.version>
    <camel.version>3.22.1</camel.version>

But stops working with:

    <spring-boot.version>3.0.2</spring-boot.version>
    <camel.version>4.0.0-M1</camel.version>

and upwards

Tested with corretto-18 and corretto-21

I made a sample repo to reproduce the issue: https://github.com/rlratcliffe/openapi27-test. Separate commits for working vs not working. Instructions below. I recognize that this could be more of a Camel problem, but since it worked previously on the older versions of SB/devtools I thought I would try here first. Thank you for your time.

Clone the repo mentioned above and then:

---

Working with old versions:

1. git checkout 3fec6482c5042d6bc944771ab9ddd7dbd223c9a6
2. In Intellij, Run CamelApplication.main()
3. Once application is started, in a terminal curl http://localhost:9000/api/hello which should output "hola"
4. Edit RoutesImplementation line 21 to say .setBody(simple("hello"))
5. Build -> Build Project

Expected result: SB application restarts, Camel routes also restart and curl http://localhost:9000/api/hello == "hello"
Actual result: same as expected result

6. Stop application

---

Not working with new versions:

1. Reset your changes to RoutesImplementation with git restore . or similar
2. git checkout ab358fc7756bf8a7c3f341ada447cbc739e681c5
3. In Intellij, Run CamelApplication.main()
4. Once application is started, in a terminal curl http://localhost:9000/api/hello which should output "hola"
5. Edit RoutesImplementation line 21 to say .setBody(simple("hello"))
6. Build -> Build Project

Expected result: SB application restarts, Camel routes also restart and curl http://localhost:9000/api/hello == "hello"
Actual result: Camel routes stop and curl http://localhost:9000/api/hello == "Connection refused"

[wilkinsona]

Thanks for the sample. With commit ca981de8, the restart appears to be getting stuck here:

"restartedMain" #72 prio=5 os_prio=31 cpu=102720.08ms elapsed=103.39s tid=0x00007fc7c8810600 nid=0xb60f runnable  [0x000070000627c000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.StackTraceElement.initStackTraceElements(java.base@17.0.1/Native Method)
	at java.lang.StackTraceElement.of(java.base@17.0.1/StackTraceElement.java:541)
	at java.lang.Throwable.getOurStackTrace(java.base@17.0.1/Throwable.java:839)
	- locked <0x00000006084b9668> (a java.lang.IllegalStateException)
	at java.lang.Throwable.getStackTrace(java.base@17.0.1/Throwable.java:831)
	at io.undertow.servlet.UndertowServletLogger_$logger._copyStackTraceMinusOne(UndertowServletLogger_$logger.java:120)
	at io.undertow.servlet.UndertowServletLogger_$logger.contextDestroyed(UndertowServletLogger_$logger.java:184)
	at io.undertow.servlet.spec.ServletContextImpl.getDeploymentInfo(ServletContextImpl.java:210)
	at io.undertow.servlet.spec.ServletContextImpl.getInitParameter(ServletContextImpl.java:429)
	at org.springframework.web.context.support.ServletContextPropertySource.getProperty(ServletContextPropertySource.java:47)
	at org.springframework.web.context.support.ServletContextPropertySource.getProperty(ServletContextPropertySource.java:33)
	at org.springframework.core.env.PropertySourcesPropertyResolver.getProperty(PropertySourcesPropertyResolver.java:85)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver$DefaultResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:125)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.findPropertyValue(ConfigurationPropertySourcesPropertyResolver.java:99)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:75)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:61)
	at org.springframework.core.env.AbstractEnvironment.getProperty(AbstractEnvironment.java:552)
	at org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource.getProperty(SpringEnvironmentPropertySource.java:50)
	at org.apache.logging.log4j.util.PropertiesUtil$Environment.sourceGetProperty(PropertiesUtil.java:771)
	at org.apache.logging.log4j.util.PropertiesUtil$Environment.getStringProperty(PropertiesUtil.java:752)
	at org.apache.logging.log4j.util.PropertiesUtil.getStringProperty(PropertiesUtil.java:476)
	at org.apache.logging.log4j.util.PropertyEnvironment.getStringProperty(PropertyEnvironment.java:400)
	at org.apache.logging.log4j.util.LoaderUtil.newCheckedInstanceOfProperty(LoaderUtil.java:332)
	at org.apache.logging.log4j.core.impl.ContextDataInjectorFactory.createInjector(ContextDataInjectorFactory.java:69)
	at org.apache.logging.log4j.core.impl.Log4jLogEvent$Builder.initDefaultContextData(Log4jLogEvent.java:280)
	at org.apache.logging.log4j.core.impl.Log4jLogEvent$Builder.<init>(Log4jLogEvent.java:88)
	at org.apache.logging.log4j.core.impl.Log4jLogEvent.newBuilder(Log4jLogEvent.java:290)
	at org.apache.logging.log4j.core.impl.DefaultLogEventFactory.createEvent(DefaultLogEventFactory.java:113)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:529)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:92)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:168)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2784)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2737)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2723)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2478)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2249)
	at org.apache.commons.logging.LogAdapter$Log4jLog.log(LogAdapter.java:264)
	at org.apache.commons.logging.LogAdapter$Log4jLog.info(LogAdapter.java:224)
	at org.springframework.boot.StartupInfoLogger.logStarting(StartupInfoLogger.java:50)
	at org.springframework.boot.SpringApplication.logStartupInfo(SpringApplication.java:638)
	at org.springframework.boot.SpringApplication.prepareContext(SpringApplication.java:404)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:333)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1354)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
	at dev.rlratcliffe.CamelApplication.main(CamelApplication.java:22)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.1/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.1/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.1/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@17.0.1/Method.java:568)
	at org.springframework.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:50)

Undertow is trying to throw the exception reported in #33450 but, for a reason that's unknown to me, the JVM's unable to fill in the exception's stack trace. This is the problem mentioned by @koww in #33450 (comment). The fact that the JVM's getting stuck when filling in the stack trace, means that the fix in Log4j2 to catch and swallow the exception does not help.

I'm going to close this is a duplicate of #33450 as I don't think there's anything unique to your situation that needs to be tracked separately.

[wilkinsona]

On further investigation, I no longer consider this issue to be a duplicate.

The JVM isn't getting stuck when filling in the stack trace, it's in an infinite loop due to some behavior of Log4j2 3.0 beta 1:

Looking more closely at the hang that can be reproduced using the app provided in #40178, it isn't actually a hang but what appears to be an infinite loop in org.apache.logging.log4j.util.PropertiesUtil.Environment:

while (source != null) {
   result = sourceGetProperty(source, contextKey);
   if (result != null) {
       return result;
   }
   source = sources.higher(source);
}

sources contains 6 PropertySource instances but higher(source) is flip-flopping between two of them:

org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource@d0fbaa3
org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource@1b375f0b

I'm not sure why there are two instances of SpringEnvironmentPropertySource but I think that may be triggering a bug in Log4j2's comparison of property sources, perhaps because they have the same priority.

The presence of the two instances is, as far as I can tell, due to Devtools. The first instance is added when the app starts and the second is added when a change is made that triggers a restart. We need to clean up SpringEnvironmentPropertySource as part of a context being closed otherwise it'll hold onto an Environment indefinitely.

[wilkinsona]

The presence of the two instances is, as far as I can tell, due to Devtools

It's not just due to Devtools. The problem also occurs if you run one app after the other in the same JVM, like so:

SpringApplication.run(SampleActuatorLog4J2Application.class).close();
SpringApplication.run(SampleActuatorLog4J2Application.class).close();

With Log4j2 3.0 beta 1, this will produce an infinite loop as we end up with two SpringEnvironmentPropertySource that then flip-flop as described above. With Log4j2 2.x, the attempt to add the second SpringEnvironmentPropertySource has no effect as it's rejected due to the presence of a property source with the same priority. The behavior changed in 3.0 beta 1 in this commit.

There's still a problem with Logj2 2.x as being stuck with the first SpringEnvironmentPropertySource means that any changes to the environment are ignored. For example:

SpringApplication.run(SampleActuatorLog4J2Application.class, "--example=first").close();
SpringApplication.run(SampleActuatorLog4J2Application.class, "--example=second").close();

Log4j2 will always see first as the value of the example property even once the first context has been closed and the second has been refreshed.

I think we need apache/logging-log4j2#2454 in order to fix this as it adds a removePropertySource method. That will allow us to remove the SpringEnvironmentPropertySource when we're cleaning up the logging system. When the second initialization happens it should then be able to add its property source without it being rejected (Log4j 2.x) or becoming a duplicate (Log4j 3.x).

/cc @ppkarwasz @rgoers

[wilkinsona]

@rlratcliffe Here's a hack that gets restarts working again with Log4j2 3.0 beta 1:

    public static void main(String[] args) {
    	SpringApplication app = new SpringApplication(CamelApplication.class);
    	app.addListeners(new ApplicationListener<ContextClosedEvent>() {

			@Override
			public void onApplicationEvent(ContextClosedEvent event) {
				PropertiesUtil properties = PropertiesUtil.getProperties();
				try {
					Field environmentField = properties.getClass().getDeclaredField("environment");
					environmentField.setAccessible(true);
					Object environment = environmentField.get(properties);
					Field sourcesField = environment.getClass().getDeclaredField("sources");
					sourcesField.setAccessible(true);
					@SuppressWarnings("unchecked")
					Set<PropertySource> sources = (Set<PropertySource>) sourcesField.get(environment);
					Iterator<PropertySource> iterator = sources.iterator();
					while (iterator.hasNext()) {
						PropertySource candidate = iterator.next();
						if ("org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource".equals(candidate.getClass().getName())) {
							iterator.remove();
							System.out.println("Removed " + candidate);
						}
					}
				}
				catch (Exception ex) {
					ex.printStackTrace();
				}
			}
    		
    	});
    	app.run(args);
    }

This will be much more elegant once removePropertySource is available to some code that can keep track of the SpringEnvironmentPropertySource instance that needs to be removed.