Undertow throws exception on shutdown when using Log4j2 #33450

leonardwoo · 2022-12-03T03:46:24Z

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)

The text was updated successfully, but these errors were encountered:

mhalbritter · 2022-12-05T09:02:06Z

Can be reproduced using this:
gh-33450.zip

jagilberteExtInditex · 2022-12-28T15:21:33Z

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)

koww · 2023-03-29T13:50:43Z

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 = [&quot;test&quot;], 
propertySourceLocations = [], 
propertySourceProperties = [&quot;org.springframework.boot.test.context.SpringBootTestContextBootstrapper=true&quot;, &quot;spring.main.web-application-type=none&quot;], 
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 · 2023-05-02T11:38:51Z

#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 · 2023-09-18T21:41:57Z

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 · 2023-11-16T13:05:06Z

I have two fixes for this in my branch:

0a5c21f removes the ServletContextPropertySource on shutdown
c52ad97 introduces a stop method on the SpringEnvironmentPropertySource, which then disables property lookups.

I think c52ad97 is the cleaner solution, but this does not only remove the ServletContextPropertySource but all of the Spring Environment from Log4j. WDYT?

rgoers · 2023-11-16T14:26:23Z

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 · 2023-11-16T14:45:52Z

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 · 2023-11-20T21:25:38Z

@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 · 2023-12-05T05:04:56Z

I ended up creating unit tests and verifying the fix without Spring since the issue was easy to reproduce. See apache/logging-log4j2#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 · 2023-12-23T06:02:02Z

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

mhalbritter · 2024-01-09T12:50:53Z

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

prathee1228 · 2024-02-26T05:46:54Z

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

rgoers · 2024-02-26T06:12:47Z

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 · 2024-03-20T18:22:35Z

@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(java.base@17.0.10/Native Method)
        at java.lang.StackTraceElement.of(java.base@17.0.10/StackTraceElement.java:541)
        at java.lang.Throwable.getOurStackTrace(java.base@17.0.10/Throwable.java:839)
        - locked <0x00000000f5c473c0> (a java.lang.IllegalStateException)
        at java.lang.Throwable.getStackTrace(java.base@17.0.10/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 · 2024-04-11T16:34:51Z

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 · 2024-04-11T17:00:32Z

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 · 2024-04-11T18:52:23Z

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

koww · 2024-04-17T17:48:11Z

@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 · 2024-04-17T18:28:02Z

@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 · 2024-04-17T20:30:12Z

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 · 2024-04-19T10:40:32Z

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 · 2024-04-19T13:24:57Z

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

wilkinsona · 2024-04-19T13:32:45Z

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 #40327 so the workaround is no longer needed. With either of these changes in place, gradle test completes successfully.

wilkinsona · 2024-04-19T13:39:00Z

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 · 2024-04-19T14:14:26Z

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

spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Dec 3, 2022

mhalbritter added type: bug A general bug and removed status: waiting-for-triage An issue we've not yet triaged labels Dec 5, 2022

mhalbritter added this to the 3.0.x milestone Dec 5, 2022

mhalbritter changed the title ~~Shutdown Exception - This Context has been already destroyed~~ Undertow throws exception on shutdown when using Log4j2 Dec 5, 2022

This comment was marked as resolved.

Sign in to view

mehdihasan mentioned this issue Mar 27, 2023

Update to JDK 17 and SpringBoot 3 obsidiandynamics/kafdrop#482

Merged

davideicardi mentioned this issue Apr 1, 2023

Error during shutdown obsidiandynamics/kafdrop#496

Closed

rgoers mentioned this issue Sep 18, 2023

Spring Boot shudown fails with an error apache/logging-log4j2#1799

Closed

philwebb modified the milestones: 3.0.x, 3.1.x Nov 8, 2023

ppkarwasz mentioned this issue Jan 11, 2024

Fix 1799 and Spring 33450 apache/logging-log4j2#2062

Merged

This was referenced Apr 9, 2024

Backport part of #2062 to 2.x branch. apache/logging-log4j2#2454

Merged

spring boot 3.2.4 + spring-boot-starter-log4j2 + spring-boot-starter-undertow apache/logging-log4j2#2453

Closed

wilkinsona mentioned this issue Apr 11, 2024

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

Closed

This comment was marked as duplicate.

Sign in to view

wilkinsona closed this as not planned Won't fix, can't repro, duplicate, stale Apr 19, 2024

wilkinsona removed this from the 3.1.x milestone Apr 19, 2024

wilkinsona added the status: superseded An issue that has been superseded by another label Apr 19, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Undertow throws exception on shutdown when using Log4j2 #33450

Undertow throws exception on shutdown when using Log4j2 #33450

leonardwoo commented Dec 3, 2022

mhalbritter commented Dec 5, 2022

jagilberteExtInditex commented Dec 28, 2022

This comment was marked as resolved.

koww commented Mar 29, 2023

wilkinsona commented May 2, 2023

rgoers commented Sep 18, 2023

mhalbritter commented Nov 16, 2023 •

edited

Loading

rgoers commented Nov 16, 2023 •

edited

Loading

wilkinsona commented Nov 16, 2023

rgoers commented Nov 20, 2023

rgoers commented Dec 5, 2023

rgoers commented Dec 23, 2023

mhalbritter commented Jan 9, 2024

prathee1228 commented Feb 26, 2024

rgoers commented Feb 26, 2024

koww commented Mar 20, 2024

wilkinsona commented Apr 11, 2024

wilkinsona commented Apr 11, 2024 •

edited

Loading

wilkinsona commented Apr 11, 2024 •

edited

Loading

This comment was marked as duplicate.

koww commented Apr 17, 2024 •

edited

Loading

wilkinsona commented Apr 17, 2024

koww commented Apr 17, 2024 •

edited

Loading

wilkinsona commented Apr 19, 2024

koww commented Apr 19, 2024 •

edited

Loading

wilkinsona commented Apr 19, 2024 •

edited

Loading

wilkinsona commented Apr 19, 2024 •

edited

Loading

koww commented Apr 19, 2024

Undertow throws exception on shutdown when using Log4j2 #33450

Undertow throws exception on shutdown when using Log4j2 #33450

Comments

leonardwoo commented Dec 3, 2022

mhalbritter commented Dec 5, 2022

jagilberteExtInditex commented Dec 28, 2022

This comment was marked as resolved.

koww commented Mar 29, 2023

wilkinsona commented May 2, 2023

rgoers commented Sep 18, 2023

mhalbritter commented Nov 16, 2023 • edited Loading

rgoers commented Nov 16, 2023 • edited Loading

wilkinsona commented Nov 16, 2023

rgoers commented Nov 20, 2023

rgoers commented Dec 5, 2023

rgoers commented Dec 23, 2023

mhalbritter commented Jan 9, 2024

prathee1228 commented Feb 26, 2024

rgoers commented Feb 26, 2024

koww commented Mar 20, 2024

wilkinsona commented Apr 11, 2024

wilkinsona commented Apr 11, 2024 • edited Loading

wilkinsona commented Apr 11, 2024 • edited Loading

This comment was marked as duplicate.

koww commented Apr 17, 2024 • edited Loading

wilkinsona commented Apr 17, 2024

koww commented Apr 17, 2024 • edited Loading

wilkinsona commented Apr 19, 2024

koww commented Apr 19, 2024 • edited Loading

wilkinsona commented Apr 19, 2024 • edited Loading

wilkinsona commented Apr 19, 2024 • edited Loading

koww commented Apr 19, 2024

mhalbritter commented Nov 16, 2023 •

edited

Loading

rgoers commented Nov 16, 2023 •

edited

Loading

wilkinsona commented Apr 11, 2024 •

edited

Loading

wilkinsona commented Apr 11, 2024 •

edited

Loading

koww commented Apr 17, 2024 •

edited

Loading

koww commented Apr 17, 2024 •

edited

Loading

koww commented Apr 19, 2024 •

edited

Loading

wilkinsona commented Apr 19, 2024 •

edited

Loading

wilkinsona commented Apr 19, 2024 •

edited

Loading