Log4j2LoggingSystem may still try to fetch properties from SpringEnvironmentPropertySource on shutdown #43430
Comments
spring-projects-issues
added
the
status: waiting-for-triage
philwebb
added
type: bug
|
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? |
wilkinsona
added
the
status: waiting-for-feedback
|
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:
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 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:
In this case |
spring-projects-issues
added
status: feedback-provided
|
Thanks for the additional details. Unfortunately, I don't understand how your application is getting into the described situation. If a 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? |
wilkinsona
added
status: waiting-for-feedback
|
In my case, property source is registered in Registration in I've updated sample app sample-app-v2.tar.gz. This time issue reproducibility depends on But, just in case, I've placed patched |
spring-projects-issues
added
status: feedback-provided
|
Thanks. With that latest information, I think I may have reproduced what you have described using the following: package com.pleeco.core.springbootsigterm;
import java.util.concurrent.CountDownLatch;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.boot.context.event.ApplicationEnvironmentPreparedEvent;
import org.springframework.boot.context.logging.LoggingApplicationListener;
import org.springframework.context.ApplicationListener;
import org.springframework.core.Ordered;
import org.springframework.core.env.PropertySource;
@SpringBootApplication
public class SpringBootSigtermApplication {
public static void main(String[] args) {
new SpringApplicationBuilder(SpringBootSigtermApplication.class)
.listeners(new TestApplicationListener())
.run(args);
}
static class TestApplicationListener implements ApplicationListener<ApplicationEnvironmentPreparedEvent>, Ordered {
@Override
public int getOrder() {
return LoggingApplicationListener.DEFAULT_ORDER + 10;
}
@Override
public void onApplicationEvent(ApplicationEnvironmentPreparedEvent event) {
event.getEnvironment().getPropertySources().addLast(new TestPropertySource("test"));
}
}
static class TestPropertySource extends PropertySource<Object> {
private final CountDownLatch socketAvailable = new CountDownLatch(1);
public TestPropertySource(String name) {
super(name);
}
@Override
public String getProperty(String name) {
try {
this.socketAvailable.await();
} catch (InterruptedException ex) {
Thread.currentThread().interrupt();
}
return null;
}
}
}When the application's started, the If I send Is this an accurate reproduction of the problem that you're seeing? |
wilkinsona
added
status: waiting-for-feedback
|
Yes, that's exactly the problem that I observe. My initial idea was to:
But it fails due to undefined other of execution of shutdown handlers.
While trying to find a solution, I've patched |
spring-projects-issues
added
status: feedback-provided
philwebb
added
type: bug
|
Note that Log4j 2.24.0 and later ignores exceptions thrown by property sources (see apache/logging-log4j2#2454), so it shouldn't be affected by this problem. |
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
SIGTERMduring application startup afterApplicationEnvironmentPreparedEvent, but beforeApplicationContextInitializedEvent, Log4j2 (and other logging systems) will run shutdown handler inSpringApplicationShutdownHook, i.e. the one that is returned byorg.springframework.boot.logging.log4j2.Log4J2LoggingSystem#getShutdownHandler. During shutdown it will try to read some properties (i.e.log4j2.disable.jmx) fromSpringEnvironmentPropertySourcewhich still holds reference to underlying environment.Attaching small repro of this issue: sample-app.tar.gz
The text was updated successfully, but these errors were encountered: