Undertow throws exception on shutdown when using Log4j2

[leonardwoo]

When I shutdown serivce, has this.

Work with Spring boot 3.0.0, Undertow and Log4j2

Exception in thread "SpringApplicationShutdownHook" java.lang.IllegalStateException: UT015023: This Context has been already destroyed
        at io.undertow.servlet.spec.ServletContextImpl.getDeploymentInfo(ServletContextImpl.java:210)
        at io.undertow.servlet.spec.ServletContextImpl.getInitParameterNames(ServletContextImpl.java:434)
        at org.springframework.web.context.support.ServletContextPropertySource.getPropertyNames(ServletContextPropertySource.java:41)
        at org.springframework.core.env.EnumerablePropertySource.containsProperty(EnumerablePropertySource.java:74)
        at org.springframework.core.env.PropertySourcesPropertyResolver.containsProperty(PropertySourcesPropertyResolver.java:51)
        at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.containsProperty(ConfigurationPropertySourcesPropertyResolver.java:55)
        at org.springframework.core.env.AbstractEnvironment.containsProperty(AbstractEnvironment.java:546)
        at org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource.containsProperty(SpringEnvironmentPropertySource.java:55)
        at org.apache.logging.log4j.util.PropertiesUtil$Environment.get(PropertiesUtil.java:537)
        at org.apache.logging.log4j.util.PropertiesUtil$Environment.access$200(PropertiesUtil.java:444)
        at org.apache.logging.log4j.util.PropertiesUtil.getStringProperty(PropertiesUtil.java:392)
        at org.apache.logging.log4j.util.PropertiesUtil.getBooleanProperty(PropertiesUtil.java:179)
        at org.apache.logging.log4j.status.StatusLogger.isDebugPropertyEnabled(StatusLogger.java:143)
        at org.apache.logging.log4j.status.StatusLogger.isEnabled(StatusLogger.java:426)
        at org.apache.logging.log4j.status.StatusLogger.isEnabled(StatusLogger.java:348)
        at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1906)
        at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:458)
        at org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:355)
        at org.apache.logging.log4j.core.AbstractLifeCycle.stop(AbstractLifeCycle.java:136)
        at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.lambda$getShutdownHandler$2(Log4J2LoggingSystem.java:446)
        at java.base/java.lang.Iterable.forEach(Iterable.java:75)
        at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:110)
        at java.base/java.lang.Thread.run(Thread.java:833)

[mhalbritter]

Can be reproduced using this: gh-33450.zip

[jagilberteExtInditex]

I also get errors with Undertow when is shutting down but with HikariDataSource:

2022-12-28T16:17:59.128+01:00  INFO 14276 --- [ionShutdownHook] i.undertow                               : stopping server: Undertow - 2.3.0.Final
2022-12-28T16:17:59.131+01:00  INFO 14276 --- [ionShutdownHook] i.u.servlet                              : Destroying Spring FrameworkServlet 'dispatcherServlet'
[SpringApplicationShutdownHook] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated...
[SpringApplicationShutdownHook] INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed.
Exception in thread "SpringApplicationShutdownHook" java.lang.IllegalStateException: UT015023: This Context has been already destroyed
	at io.undertow.servlet.spec.ServletContextImpl.getDeploymentInfo(ServletContextImpl.java:210)
	at io.undertow.servlet.spec.ServletContextImpl.getInitParameterNames(ServletContextImpl.java:434)
	at org.springframework.web.context.support.ServletContextPropertySource.getPropertyNames(ServletContextPropertySource.java:41)
	at org.springframework.core.env.EnumerablePropertySource.containsProperty(EnumerablePropertySource.java:74)
	at org.springframework.core.env.PropertySourcesPropertyResolver.containsProperty(PropertySourcesPropertyResolver.java:51)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.containsProperty(ConfigurationPropertySourcesPropertyResolver.java:55)
	at org.springframework.core.env.AbstractEnvironment.containsProperty(AbstractEnvironment.java:546)
	at org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource.containsProperty(SpringEnvironmentPropertySource.java:55)
	at org.apache.logging.log4j.util.PropertiesUtil$Environment.get(PropertiesUtil.java:537)
	at org.apache.logging.log4j.util.PropertiesUtil$Environment.access$200(PropertiesUtil.java:444)
	at org.apache.logging.log4j.util.PropertiesUtil.getStringProperty(PropertiesUtil.java:392)
	at org.apache.logging.log4j.util.PropertiesUtil.getBooleanProperty(PropertiesUtil.java:179)
	at org.apache.logging.log4j.status.StatusLogger.isDebugPropertyEnabled(StatusLogger.java:143)
	at org.apache.logging.log4j.status.StatusLogger.isEnabled(StatusLogger.java:426)

[wilkinsona]

@lakxtxue A duplicate stack trace isn't particularly valuable and adds quite a bit of noise. A 👍 on the original description of the issue is enough to let us know that you have the same problem.

[koww]

I am encountering the same issue in tests. Using SpringBoot 3.0.3, JUnit5, and gradle 7.4.2.

[Test worker] [ERROR] [org.springframework.test.context.TestContextManager] [Caught exception while allowing TestExecutionListener [org.springframework.boot.test.mock.mockito.MockitoTestExecutionListener] to prepare test instance [some.test.package.SomeTestClass@69c071db]]
java.lang.IllegalStateException: Failed to load ApplicationContext for 
[MergedContextConfiguration@3186b07d 
testClass = some.test.package.SomeTestClass, 
locations = [], 
classes = [some.test.package.SomeTestClass], 
contextInitializerClasses = [], 
activeProfiles = ["test"], 
propertySourceLocations = [], 
propertySourceProperties = ["org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true", "spring.main.web-application-type=none"], 
contextCustomizers = [org.springframework.boot.test.autoconfigure.actuate.observability.ObservabilityContextCustomizerFactory$DisableObservabilityContextCustomizer@9da1, org.springframework.boot.test.autoconfigure.properties.PropertyMappingContextCustomizer@0, org.springframework.boot.test.autoconfigure.web.servlet.WebDriverContextCustomizerFactory$Customizer@bdecc21, org.springframework.boot.test.context.filter.ExcludeFilterContextCustomizer@abbc908, org.springframework.boot.test.json.DuplicateJsonObjectContextCustomizerFactory$DuplicateJsonObjectContextCustomizer@5f84abe8, org.springframework.boot.test.mock.mockito.MockitoContextCustomizer@e1f277c6, org.springframework.boot.test.web.client.TestRestTemplateContextCustomizer@160396db, org.springframework.boot.test.context.SpringBootTestAnnotation@6e5fe9d4], 
contextLoader = org.springframework.boot.test.context.SpringBootContextLoader, parent = null]

Any insights would be much appreciated.

[wilkinsona]

https://github.com/spring-projects/spring-boot/issues/35184 is somewhat related to this. A fix for 35184 may change how things behave here too. If it doesn't solve the problem (I suspect that it won't), we may have to see if it's possible to remove the ServletContextPropertySource from the environment when the web server is stopped or perhaps even remove SpringEnvironmentPropertySource from Log4j2 when the application context is closed.

[rgoers]

I just saw this and will look into whether this can be addressed in Log4j itself. I am seeing a different, but related, error when shutting down a sample Spring Boot app.

[mhalbritter]

I have two fixes for this in my branch:

• https://github.com/spring-projects/spring-boot/commit/0a5c21fb2d746ff7fbe729f20b42ddac41371192 removes the ServletContextPropertySource on shutdown
• https://github.com/spring-projects/spring-boot/commit/c52ad976df6682e9788f9706ad73575699d1ac52 introduces a stop method on the SpringEnvironmentPropertySource, which then disables property lookups.

I think https://github.com/spring-projects/spring-boot/commit/c52ad976df6682e9788f9706ad73575699d1ac52 is the cleaner solution, but this does not only remove the ServletContextPropertySource but all of the Spring Environment from Log4j. WDYT?

[rgoers]

I have a fix for this in Log4j that I am testing. It simply catches the exception and ignores the PropertySource. However, testing has been difficult as I am trying to upgrade one of my existing services from Spring Boot 2 to Spring Boot 3 and it is painful.

[wilkinsona]

I am trying to upgrade one of my existing services from Spring Boot 2 to Spring Boot 3 and it is painful

Sorry to hear that. If there are things missing from https://github.com/spring-projects/spring-boot/wiki/Spring-Boot-3.0-Migration-Guide please let us know by opening an issue. The guide works best when upgrading from 2.7.x to 3.0.x. From there you can then upgrade to 3.1.x.

[rgoers]

@wilkinsona The issue is just that we have several support libraries that have to be upgraded. One uses the openapi generator so that has to be upgraded and have issues fixed. Then I have to figure out how to modify our CI system to be able to release the library while still supporting Spring 2 (i.e. - a different branch is needed which our CI wasn't designed for). Just a big can of worms. Nothing you can help with. Most of this is Oracle's fault for inflicting the package renaming on us.

[rgoers]

I ended up creating unit tests and verifying the fix without Spring since the issue was easy to reproduce. See https://github.com/apache/logging-log4j2/pull/2062. This will be available in our next Log4j 3.x beta release for testing. 3.x is specifically targeted for Java 17 and Spring Boot 3.x. The fix can be tested now if you use a Log4j 3.x SNAPSHOT.

[rgoers]

Log4j 3.0.0-beta1 has been releaesd. Please try with that version to verify the problem has been resolved.

[mhalbritter]

I can confirm that using Boot 3.3.0-SNAPSHOT with Log4J2 3.0.0-beta1 fixes this problem.

[prathee1228]

Is there any plan to port the changes to log4j2 2.x with Spring boot 3.2 version?

[rgoers]

We are going to have to since we have decided to continue using Log4j-API 2.x with Log4j 3.x when 3.x is released.

[koww]

@rgoers @mhalbritter As I tried with SB 3.3.0-M2 and Log4j2 3.0.0-beta2 with JDK 17.0.9/17.0.10, the exception is not thrown.

Yet the JVM stuck in native method:

"Test worker" #1 prio=5 os_prio=0 cpu=22954.84ms elapsed=91.28s tid=0x00007f2578036320 nid=0x3785 runnable  [0x00007f2581239000]
   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 <0x00000000f5c473c0> (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:123)
        at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.findPropertyValue(ConfigurationPropertySourcesPropertyResolver.java:97)
        at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:74)
        at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:60)
        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.core.annotation.OnPropertyKeyCondition.matches(OnPropertyKeyCondition.java:41)
        at org.apache.logging.log4j.plugins.di.DefaultInstanceFactory.lambda$registerBundle$12(DefaultInstanceFactory.java:272)
        at org.apache.logging.log4j.plugins.di.DefaultInstanceFactory$$Lambda$514/0x00007f25041b8000.test(Unknown Source)
        ...

where the

        at io.undertow.servlet.UndertowServletLogger_$logger._copyStackTraceMinusOne(UndertowServletLogger_$logger.java:120)
        at io.undertow.servlet.UndertowServletLogger_$logger.contextDestroyed(UndertowServletLogger_$logger.java:184)

are from some generated code that I'm not faimiliar with either.

Meanwhile the perf top shows top symbols called are

   8.70%  libjvm.so           [.] java_lang_Throwable::fill_in_stack_trace
   7.79%  libjvm.so           [.] InstanceKlass::method_with_orig_idnum
   7.79%  libjvm.so           [.] StringTable::intern
   6.20%  libjvm.so           [.] StringTable::do_lookup
  ...

I cannot tell if this is the continuation of the same problem, or it's a new problem with log4j2 or undertow or springboot. Any insights will be much appreciated.

[wilkinsona]

The hang's also been seen by another user. It looks to me like a different symptom of the same problem. The fact that the JVM's apparently getting stuck when Undertow's trying to throw the exception renders the fix in Log4j2 ineffective. We may have to look at an alternative that stops the exception being thrown in the first place.

[wilkinsona]

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]

I'm going to re-open #40178 as, unlike the problem reported through this issue, the problem isn't specific to Undertow.

[arunpaljava]

I also get errors with Undertow when is shutting down.

stopping server: Undertow - 2.3.10.Final
ERROR StatusConsoleListener Unable to unregister MBeans
 java.lang.IllegalStateException: UT015023: This Context has been already destroyed
        at io.undertow.servlet.spec.ServletContextImpl.getDeploymentInfo(ServletContextImpl.java:210)
        at io.undertow.servlet.spec.ServletContextImpl.getInitParameterNames(ServletContextImpl.java:434)
        at org.springframework.web.context.support.ServletContextPropertySource.getPropertyNames(ServletContextPropertySource.java:41)
        at org.springframework.core.env.EnumerablePropertySource.containsProperty(EnumerablePropertySource.java:74)
        at org.springframework.core.env.PropertySourcesPropertyResolver.containsProperty(PropertySourcesPropertyResolver.java:51)
        at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.containsProperty(ConfigurationPropertySourcesPropertyResolver.java:55)
        at org.springframework.core.env.AbstractEnvironment.containsProperty(AbstractEnvironment.java:546)
        at org.springframework.boot.logging.log4j2.SpringEnvironmentPropertySource.containsProperty(SpringEnvironmentPropertySource.java:55)
        at org.apache.logging.log4j.util.PropertiesUtil$Environment.get(PropertiesUtil.java:530)
        at org.apache.logging.log4j.util.PropertiesUtil$Environment.access$200(PropertiesUtil.java:444)
        at org.apache.logging.log4j.util.PropertiesUtil.getStringProperty(PropertiesUtil.java:392)
        at org.apache.logging.log4j.util.PropertiesUtil.getBooleanProperty(PropertiesUtil.java:165)
        at org.apache.logging.log4j.util.PropertiesUtil.getBooleanProperty(PropertiesUtil.java:154)
        at org.apache.logging.log4j.core.jmx.Server.isJmxDisabled(Server.java:131)
        at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:244)
        at org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:364)
        at org.apache.logging.log4j.core.AbstractLifeCycle.stop(AbstractLifeCycle.java:136)
        at org.springframework.boot.logging.log4j2.Log4J2LoggingSystem.lambda$getShutdownHandler$2(Log4J2LoggingSystem.java:452)
        at java.base/java.lang.Iterable.forEach(Iterable.java:75)
        at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:116)
        at java.base/java.lang.Thread.run(Thread.java:842)

[koww]

@wilkinsona Thank you for the check. I tried the hack you mentioned in the other issue, yet it didn't help in my case. If I'm understanding it correctly, Undertow is using jboss logging by default and will generate some internal logger instance during the runtime, so the hack for Log4j2 is not working. Yet I believe Undertow accepts properties file to configure the logging provider, through which we can provide log4j as the logging provider, thus we can try resolve it using methods mentioned in #40178, but is it possible to pass the configuration from application.properties?

[wilkinsona]

@koww I'm not sure why it hasn't worked in your case as, judging by the stack trace, it appears to be the same. Perhaps you can share some code that reproduces your problem so we can investigate further.

[koww]

sample.zip @wilkinsona Please see attached file for reproducing the case I met. All I did was to run ./gradlew clean build with java 17.0.10

$JAVA_HOME/bin/java -version
openjdk version "17.0.10" 2024-01-16
OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7)
OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing)

And if you disable one of the test classes the build will pass.

[wilkinsona]

That zip seems to contain only a sample/ directory:

$ unzip -l sample.zip 
Archive:  sample.zip
  Length      Date    Time    Name
---------  ---------- -----   ----
        0  04-17-2024 21:22   sample/
---------                     -------
        0                     1 file

[koww]

@wilkinsona My bad. Please see this file: sample.zip

[wilkinsona]

You've configured the workaround in your application's main method but your tests aren't configured to use it. You can correct that like this:

@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT, useMainMethod = UseMainMethod.ALWAYS)

Alternatively, you can upgrade from 3.3.0-M2 to 3.3.0-RC1 and pick up the fix for https://github.com/spring-projects/spring-boot/issues/40327 so the workaround is no longer needed. With either of these changes in place, gradle test completes successfully.

[wilkinsona]

Revisiting @mhalbritter's reproducer and the sample shared above modified to use Log4j 2.x, the fix for #40178 has fixed this problem too. If you're affected by this problem please upgrade to Spring Boot 3.1.11, 3.2.5, or later.

[koww]

@wilkinsona I have verified that upgrading to SpringBoot 3.2.5 fixed my issue. Thank you for the help!