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

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

Closed
rlratcliffe opened this issue Apr 5, 2024 · 11 comments
Labels
type: bug A general bug
Milestone

Comments

@rlratcliffe
Copy link

rlratcliffe commented Apr 5, 2024

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

  1. 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"

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Apr 5, 2024
@wilkinsona
Copy link
Member

wilkinsona commented Apr 11, 2024

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([email protected]/Native Method)
	at java.lang.StackTraceElement.of([email protected]/StackTraceElement.java:541)
	at java.lang.Throwable.getOurStackTrace([email protected]/Throwable.java:839)
	- locked <0x00000006084b9668> (a java.lang.IllegalStateException)
	at java.lang.Throwable.getStackTrace([email protected]/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([email protected]/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke([email protected]/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke([email protected]/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke([email protected]/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 wilkinsona closed this as not planned Won't fix, can't repro, duplicate, stale Apr 11, 2024
@wilkinsona wilkinsona added status: duplicate A duplicate of another issue and removed status: waiting-for-triage An issue we've not yet triaged labels Apr 11, 2024
@wilkinsona
Copy link
Member

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 wilkinsona reopened this Apr 11, 2024
@wilkinsona
Copy link
Member

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 wilkinsona removed the status: duplicate A duplicate of another issue label Apr 11, 2024
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Apr 11, 2024
@wilkinsona
Copy link
Member

@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.

@wilkinsona wilkinsona changed the title spring-boot-devtools reloading not working with Camel 4 routes in SB 3 project Log4j2LoggingSystem pollutes Log4j2's environment with a SpringEnvironmentPropertySource that is never removed Apr 11, 2024
@wilkinsona wilkinsona added type: bug A general bug status: blocked An issue that's blocked on an external project change and removed status: waiting-for-triage An issue we've not yet triaged labels Apr 11, 2024
@wilkinsona wilkinsona added this to the 3.x milestone Apr 11, 2024
@ppkarwasz
Copy link
Contributor

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).

Yes, unfortunately you need for 2.24.0 to come out to use the new PropertiesUtil#removePropertySource method (or the already published 3.0.0-beta2). I'll merge the apache/logging-log4j2#2454 PR tomorrow and make a draft PR in Spring Boot, so you can test it.

@wilkinsona wilkinsona removed the status: blocked An issue that's blocked on an external project change label Apr 12, 2024
@wilkinsona wilkinsona modified the milestones: 3.x, 3.1.x Apr 12, 2024
@wilkinsona
Copy link
Member

wilkinsona commented Apr 12, 2024

I think we can minimise the damage by using a static-scoped SpringEnvironmentPropertySource, making its Environment mutable, and setting and clearing it when we initialise and clean up the logging system. We can then refine this in whatever version of Boot upgrades to 2.24.

@ppkarwasz
Copy link
Contributor

I think we can minimise the damage by using a static-scoped SpringEnvironmentPropertySource, making its Environment mutable, and setting and clearing it when we initialise and clean up the logging system. We can then refine this in whatever version of Boot upgrades to 2.24.

Sounds like a plan. That was actually the original implementation of SpringEnvironmentPropertySource in log4j-spring-boot.

@koww
Copy link

koww commented Sep 16, 2024

Per Log4j 2.24 release notes, Ignore exceptions thrown by PropertySources. (https://github.com/spring-projects/spring-boot/issues/33450), will there be refine works planned for next release?

@wilkinsona
Copy link
Member

I'm not sure that it's worth refining things as the current implementation appears to be working well. While we could change the implementation to use the new removePropertySource method as I described above, the benefits are fairly minimal as it just moves the mutable state from one place (SpringEnvironmentPropertySource tracking the environment) to another (Log4j2LoggingSystem tracking the property source). It would be more inclined to change things if we could make things immutable but that doesn't appear to be possible.

@betalb
Copy link

betalb commented Dec 5, 2024

Hello @wilkinsona
There is one case left, when environment is not cleaned on shutdown. When app receives SIGTERM during application
startup if signal arrives after ApplicationEnvironmentPreparedEvent, but before ApplicationContextInitializedEvent. In this case shutdown handler (returned by org.springframework.boot.logging.log4j2.Log4J2LoggingSystem#getShutdownHandler) will be called by code from SpringApplicationShutdownHook. During shutdown it will try to read some properties from SpringEnvironmentPropertySource which still holds reference to underlying environment.

@betalb
Copy link

betalb commented Dec 5, 2024

Submitted as new ticket and attached sample app there #43430

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug A general bug
Projects
None yet
Development

No branches or pull requests

6 participants