SpringApplicationShutdownHandlers do not run in deterministic order

[betalb]

Spring Boot version: tested on 3.2.12 and 3.4.0

This issue was mostly resolved in #40178, but one edge case still left.

When app receives SIGTERM during application startup after ApplicationEnvironmentPreparedEvent, but before ApplicationContextInitializedEvent, Log4j2 (and other logging systems) will run shutdown handler in SpringApplicationShutdownHook, i.e. the one that is returned by org.springframework.boot.logging.log4j2.Log4J2LoggingSystem#getShutdownHandler. During shutdown it will try to read some properties (i.e. log4j2.disable.jmx) from SpringEnvironmentPropertySource which still holds reference to underlying environment.

Attaching small repro of this issue: sample-app.tar.gz

[wilkinsona]

Thanks for the sample, @betalb. It has left me wondering what the real-world problem might be as closing a property source and throwing an exception from it seems a little bit artificial. Can you please describe the symptom that you saw in your real app that led to you creating a sample that fails in the manner that it does?

[betalb]

Yes, this example is really artificial. In our real case we are getting a deadlock.

Our property source, that we are trying to close, is reading properties over unix socket. If socket is not yet available, getProperty will get stuck in wait until it appears. What happens in our specific case:

1. app is launched while socket is not available
2. shutdown hook is registered via SpringApplicationShutdownHook (not explicitly, but because spring is starting to read properties during context startup)
3. app startup is suspended, waiting for socket to become available
4. app receives SIGTERM
5. SpringApplicationShutdownHook starts executing registered callbacks: one of them is log4j2 handler and other is ours, that releases the lock and interrupts the thread which is waiting for socket file

The problem is that log4j2 handler tries to read some properties and if it is executed 1st, it will be blocked by our property source, which was not yet signaled that application is shutting down. Even though, I see that actions list that are executed by SpringApplicationShutdownHook.run is wrapped into LinkedHasSet, original set of actions is backed by IdentityHashMap, so in the end the order is not defined and I can't overcome this problem by registering own shutdown hook before log4j2.

We also can't rely on other application events, because they won't be fired, as app context haven't started yet.

In following scenario problem won't occur in spring boot >= 3.2.5 and >= 3.1.11 a946f66:

1. we launch app when socket file is already available
2. app fully launches
3. socket file is removed
4. app receives SIGTERM
5. app is terminated gracefully

In this case LoggingApplicationListener.cleanupLoggingSystem will be called as reaction to ContextClosedEvent or ApplicationFailedEvent, so while executing SpringApplicationShutdownHook.run log4j2 won't have access to environment, won't hit our property source and won't be blocked.

[wilkinsona]

Thanks for the additional details. Unfortunately, I don't understand how your application is getting into the described situation. If a PropertySource that blocks is registered (either through a custom environment or an environment post-processor), I would expect it to start blocking very early and before the logging system is initialized. In my experimentation, that blocking occurs during environment post-processing:

java.lang.Exception
	at com.pleeco.core.springbootsigterm.SpringBootSigtermApplication$TestPropertySource.getProperty(SpringBootSigtermApplication.java:88)
	at com.pleeco.core.springbootsigterm.SpringBootSigtermApplication$TestPropertySource.getProperty(SpringBootSigtermApplication.java:1)
	at org.springframework.boot.context.properties.source.SpringConfigurationPropertySource.getConfigurationProperty(SpringConfigurationPropertySource.java:84)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertySource.findConfigurationProperty(ConfigurationPropertySourcesPropertySource.java:70)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.findPropertyValue(ConfigurationPropertySourcesPropertyResolver.java:91)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:75)
	at org.springframework.boot.context.properties.source.ConfigurationPropertySourcesPropertyResolver.getProperty(ConfigurationPropertySourcesPropertyResolver.java:66)
	at org.springframework.core.env.AbstractPropertyResolver.getProperty(AbstractPropertyResolver.java:191)
	at org.springframework.core.env.AbstractEnvironment.getProperty(AbstractEnvironment.java:573)
	at org.springframework.boot.reactor.ReactorEnvironmentPostProcessor.postProcessEnvironment(ReactorEnvironmentPostProcessor.java:59)
	at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEnvironmentPreparedEvent(EnvironmentPostProcessorApplicationListener.java:132)
	at org.springframework.boot.env.EnvironmentPostProcessorApplicationListener.onApplicationEvent(EnvironmentPostProcessorApplicationListener.java:115)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.doInvokeListener(SimpleApplicationEventMulticaster.java:185)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:178)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:156)
	at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:138)
	at org.springframework.boot.context.event.EventPublishingRunListener.multicastInitialEvent(EventPublishingRunListener.java:136)
	at org.springframework.boot.context.event.EventPublishingRunListener.environmentPrepared(EventPublishingRunListener.java:81)
	at org.springframework.boot.SpringApplicationRunListeners.lambda$environmentPrepared$2(SpringApplicationRunListeners.java:64)
	at java.base/java.lang.Iterable.forEach(Iterable.java:75)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:118)
	at org.springframework.boot.SpringApplicationRunListeners.doWithListeners(SpringApplicationRunListeners.java:112)
	at org.springframework.boot.SpringApplicationRunListeners.environmentPrepared(SpringApplicationRunListeners.java:63)
	at org.springframework.boot.SpringApplication.prepareEnvironment(SpringApplication.java:353)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:313)
	at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:149)
	at com.pleeco.core.springbootsigterm.SpringBootSigtermApplication.main(SpringBootSigtermApplication.java:60)

I don't think we'll be able to make a change here without a complete understanding of the problem. There's a risk of regression and that's hard to justify unless we can be confident that any change will fix the problem.

Can you please provide a sample that recreates the deadlock? Perhaps you could synthesise the role of the socket by waiting for a latch or similar that's never counted down?