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:
git checkout 3fec6482c5042d6bc944771ab9ddd7dbd223c9a6- In Intellij, Run CamelApplication.main()
- Once application is started, in a terminal
curl http://localhost:9000/api/hellowhich should output "hola" - Edit RoutesImplementation line 21 to say
.setBody(simple("hello")) - 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
- 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"
Comment From: 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 https://github.com/spring-projects/spring-boot/issues/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 https://github.com/spring-projects/spring-boot/issues/33450#issuecomment-2010310971. 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.
Comment From: 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:
java while (source != null) { result = sourceGetProperty(source, contextKey); if (result != null) { return result; } source = sources.higher(source); }
sourcescontains 6PropertySourceinstances buthigher(source)is flip-flopping between two of them:
org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource@d0fbaa3 org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource@1b375f0bI'm not sure why there are two instances of
SpringEnvironmentPropertySourcebut 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
SpringEnvironmentPropertySourceas part of a context being closed otherwise it'll hold onto anEnvironmentindefinitely.
Comment From: 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 https://github.com/apache/logging-log4j2/pull/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
Comment From: 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.
Comment From: ppkarwasz
I think we need apache/logging-log4j2#2454 in order to fix this as it adds a
removePropertySourcemethod. That will allow us to remove theSpringEnvironmentPropertySourcewhen 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.
Comment From: wilkinsona
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.
Comment From: ppkarwasz
I think we can minimise the damage by using a static-scoped
SpringEnvironmentPropertySource, making itsEnvironmentmutable, 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.
Comment From: koww
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?
Comment From: wilkinsona
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.
Comment From: betalb
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.
Comment From: betalb
Submitted as new ticket and attached sample app there https://github.com/spring-projects/spring-boot/issues/43430