Version :SpringBoot 2.7.12 The current execution process: 1. SmartLifecycle bean start with phase order. 2. tomcat start by SmartLifecycleBean 3. run bean's ContextRefreshedEvent callback.
The problem: Tomcat started port listening and received HTTP requests too early before Spring Context had fully initialized all beans. In a high-availability environment, some HTTP requests may receive unintended replies before all beans are initialized, affecting the user experience. Restrict autoStart from being executed manually after autoStart is disabled
Steps to reproduce 1. https://start.spring.io/ generate a project with Spring Web Dependencies。 2. main method code:
@SpringBootApplication
public class TomcatdemoApplication {
private static TomcatWebServer webServer;
private static final Log logger = LogFactory.getLog(TomcatdemoApplication.class);
public static void main(String[] args) {
ConfigurableApplicationContext context=SpringApplication.run(TomcatdemoApplication.class, args);
Map<String,Lifecycle> sfMap=context.getBeansOfType(Lifecycle.class);
context.start();
//try start tomcat manually,but not effect
webServer.start();
}
@Bean
public ServletWebServerFactory servletContainer() {
TomcatServletWebServerFactory tomcat = new TomcatServletWebServerFactory() {
@Override
protected TomcatWebServer getTomcatWebServer(Tomcat tomcat) {
// try disalbe auto start
webServer= new TomcatWebServer(tomcat, false, getShutdown());
return webServer;
}
};
return tomcat;
}
}
- demo SmartLifecycle code:
@Service
@Order(Ordered.HIGHEST_PRECEDENCE)
public class DemoTestSmartLifecycle implements SmartLifecycle {
private static final Log logger = LogFactory.getLog(DemoTestSmartLifecycle.class);
private volatile boolean running;
@Override
public void start() {
logger.info("start|" + LocalDateTime.now());
running=true;
}
@Override
public void stop() {
logger.info("stop|" + LocalDateTime.now());
running=false;
}
@Override
public boolean isRunning() {
return running;
}
@EventListener
@Order(Ordered.LOWEST_PRECEDENCE)
public void onContextRefreshedEvent(ContextRefreshedEvent event) {
logger.info("onContextRefreshedEvent|"+event);
}
@EventListener
@Order(Ordered.LOWEST_PRECEDENCE)
public void onContextStartedEvent(ContextStartedEvent event) {
logger.info("onContextStartedEvent|"+event);
}
@Override
public int getPhase() {
return Integer.MAX_VALUE-3;
}
}
- log show : main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): -1 (http) with context path '/tomcatdemo' and can't access http://localhost:8080/
some log :
2023-06-18 17:34:36.478 INFO 11196 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : start|2023-06-18T17:34:36.478765700
2023-06-18 17:34:36.504 INFO 11196 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): -1 (http) with context path '/tomcatdemo'
2023-06-18 17:34:36.510 INFO 11196 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : onContextRefreshedEvent|org.springframework.context.event.ContextRefreshedEvent[source=org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7d900ecf, started on Sun Jun 18 17:34:35 GMT+08:00 2023]
2023-06-18 17:34:36.512 INFO 11196 --- [ main] c.l.tomcatdemo.TomcatdemoApplication : Started TomcatdemoApplication in 0.863 seconds (JVM running for 1.034)
2023-06-18 17:34:36.514 INFO 11196 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : onContextStartedEvent|org.springframework.context.event.ContextStartedEvent[source=org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@7d900ecf, started on Sun Jun 18 17:34:35 GMT+08:00 2023]
we can know the order is : SmartLifecycle start -> Bean Refresh-> Bean Start.
I hope that the effect of optimization is as follows: 1. I can new TomcatWebServer with disalbe autostart 2. after all beans are initialized, I can start tomcat manually to listen port and receive http request.
Thanks !
the attach file is the demo project to reproduce the problem:
Comment From: quaff
You can switch jar to war then deploy it to standalone tomcat.
Comment From: wilkinsona
I'm not sure that I fully understand what you are trying to do, but I think this is working as designed. The WebServer doesn't start listening for HTTP requests until its lifecycle is started. It uses phase WebServerGracefulShutdownLifecycle.SMART_LIFECYCLE_PHASE - 1024 for this. Any component that you want to have been start()ed before this should use an appropriate phase.
If you have components that need to start after the WebServer and do not want requests to be received until they have been started, you may want to look at Boot's application availability support.
Comment From: lizongbo
I'm not sure that I fully understand what you are trying to do, but I think this is working as designed. The WebServer doesn't start listening for HTTP requests until its lifecycle is started. It uses phase
WebServerGracefulShutdownLifecycle.SMART_LIFECYCLE_PHASE - 1024for this. Any component that you want to have beenstart()ed before this should use an appropriate phase.If you have components that need to start after the WebServer and do not want requests to be received until they have been started, you may want to look at Boot's application availability support.
In the case where autoStart is true,before the callback execution of ContextRefreshedEvent and ContextStartedEvent is complete, tomcat has successfully listened on the HTTP port and can start receiving HTTP requests to execute the appropriate REST methods.
I updated the demo project, simulating sleeping for 10 seconds when receiving the ContextRefreshedEvent, and immediately accessing the http://localhost:8080/tomcatdemo/hello through the browser after starting the demo project, you can see that the log order executed is as follows:
code:
@EventListener
@Order(Ordered.LOWEST_PRECEDENCE)
public void onContextRefreshedEvent(ContextRefreshedEvent event) {
logger.info("onContextRefreshedEvent|" + event);
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
this.onrefreshed = true;
}
@EventListener
@Order(Ordered.LOWEST_PRECEDENCE)
public void onContextStartedEvent(ContextStartedEvent event) {
logger.info("onContextStartedEvent|" + event);
try {
Thread.sleep(10000);
} catch (InterruptedException e) {
e.printStackTrace();
}
this.onStarted = true;
}
the log:
2023-06-20 01:20:27.205 INFO 1972 --- [ main] c.l.tomcatdemo.TomcatdemoApplication : Starting TomcatdemoApplication using Java 17.0.7 on quickpc5 with PID 1972 (D:\githubProjects\tomcatdemo\build\classes\java\main started by 86135 in D:\githubProjects\tomcatdemo)
2023-06-20 01:20:27.206 INFO 1972 --- [ main] c.l.tomcatdemo.TomcatdemoApplication : No active profile set, falling back to 1 default profile: "default"
2023-06-20 01:20:27.656 INFO 1972 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2023-06-20 01:20:27.661 INFO 1972 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2023-06-20 01:20:27.661 INFO 1972 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.75]
2023-06-20 01:20:27.723 INFO 1972 --- [ main] o.a.c.c.C.[.[localhost].[/tomcatdemo] : Initializing Spring embedded WebApplicationContext
2023-06-20 01:20:27.723 INFO 1972 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 494 ms
2023-06-20 01:20:27.823 INFO 1972 --- [ main] o.s.b.a.w.s.WelcomePageHandlerMapping : Adding welcome page: class path resource [static/index.html]
2023-06-20 01:20:27.886 INFO 1972 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : start|2023-06-20T01:20:27.886379100
2023-06-20 01:20:27.898 INFO 1972 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path '/tomcatdemo'
2023-06-20 01:20:27.904 INFO 1972 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : onContextRefreshedEvent|org.springframework.context.event.ContextRefreshedEvent[source=org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@4a8355dd, started on Tue Jun 20 01:20:27 GMT+08:00 2023]
2023-06-20 01:20:30.727 INFO 1972 --- [nio-8080-exec-1] o.a.c.c.C.[.[localhost].[/tomcatdemo] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-06-20 01:20:30.727 INFO 1972 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2023-06-20 01:20:30.728 INFO 1972 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
2023-06-20 01:20:30.738 INFO 1972 --- [nio-8080-exec-1] com.lizongbo.tomcatdemo.DemoController : runHello
2023-06-20 01:20:37.914 INFO 1972 --- [ main] c.l.tomcatdemo.TomcatdemoApplication : Started TomcatdemoApplication in 10.889 seconds (JVM running for 11.052)
2023-06-20 01:20:37.918 INFO 1972 --- [ main] c.l.tomcatdemo.DemoTestSmartLifecycle : onContextStartedEvent|org.springframework.context.event.ContextStartedEvent[source=org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@4a8355dd, started on Tue Jun 20 01:20:27 GMT+08:00 2023]
2023-06-20 01:20:45.080 INFO 1972 --- [nio-8080-exec-2] com.lizongbo.tomcatdemo.DemoController : runHello
2023-06-20 01:20:53.456 INFO 1972 --- [nio-8080-exec-3] com.lizongbo.tomcatdemo.DemoController : runHello
the screenshot is follow：
1.
3.
so I can see this run order:
- 2023-06-20 01:20:27.886 DemoTestSmartLifecycle
- 2023-06-20 01:20:27.898 Tomcat started on port(s): 8080 (http) with context path '/tomcatdemo'
- 2023-06-20 01:20:27.904 onContextRefreshedEvent begin
- 2023-06-20 01:20:30.728 DispatcherServlet Completed initialization
- 2023-06-20 01:20:30.738 DemoController runHello ,but onrefreshed is false and onStarted is false
- 2023-06-20 01:20:37.918 onContextStartedEvent begin
- 2023-06-20 01:20:45.080 DemoController runHello ,but onrefreshed is true but onStarted is also false
- 2023-06-20 01:20:53.456 DemoController runHello ,and onrefreshed is true and onStarted is true
Between 2023-06-20 01:20:27.898 and 2023-06-20 01:20:37.918, if a large number of HTTP requests are received, their execution results may not be as expected because the app has not fully initialized and warmed up.
the new log screenshot:
the java source files :
TomcatdemoApplication.java.txt DemoController.java.txt
DemoTestSmartLifecycle.java.txt
the full project zip file:
Comment From: lizongbo
When I want to inherit the TomcatWebServer class to add custom control logic, but since the member variables in the TomcatWebServer class are private, and some fields are final, I can't inherit TomcatWebServer to achieve the effect I expect, so if I can adjust these member variables to protected, I can implement high-availability logic on my own, thank you!
Comment From: wilkinsona
ConfigurableApplicationContext context = SpringApplication.run(TomcatdemoApplication.class, args);
Map<String, Lifecycle> sfMap = context.getBeansOfType(Lifecycle.class);
context.start();
Calling start() after run() doesn't really make sense. When the context is refreshed, DefaultLifecycleProcessor.onRefresh() is called and it starts all beans. This is done immediately before the ContextRefreshedEvent is published. Calling start() on the context without having called stop() will do nothing other than publishing a ContextStartedEvent. If you want components to be started before the web server starts accepting connections, you should assign them a phase that's earlier than that of WebServerStartStopLifecycle.
You should review your use of Lifecycle, SmartLifecycle, and the context refreshed and context started events. Both events are too late to use a signal that some initialization should be performed as they will be published after the web server has started accepting requests. You could either perform any initialization as part of bean creation (or through a @PostConstruct or InitializingBean callback) or you should implement Lifecycle or SmartLifecycle with an appropriate phase to ensure that the components is started before the web server (and stopped after it).