What happened: Graceful shutdown does not work with keepalive for embedded Tomcat server. Requests are not successful. Error 500 is returned.
What you expected to happen: Graceful shutdown works, just like for embedded Jetty, embedded Undertow.
How to reproduce it: Spring boot with the following endpoints: - /url1 with a immediate result. - /url2 that returns DeferredResult\<ResponseEntity\<?>> immediately. Some result is set after 20 seconds by another thread.
application.properties content:
server.shutdown=graceful
spring.lifecycle.timeout-per-shutdown-phase=60s
I attach the appropriate code. spring-boot-gracefulshutdown-issue23437-2020-09-21-220000.zip
[n] means "terminal number n"
[1] $ git clone --depth 1 https://github.com/180254/spring-boot-gracefulshutdown-issue-23437.git [1] $ cd spring-boot-gracefulshutdown-issue-23437/demo-tomcat/ [1] $ mvn package -DskipTests [1] $ java -jar target/demo-tomcat-0.0.1-SNAPSHOT.jar [2] $ curl -v --keepalive --keepalive-time 60 "http://localhost:8080/url1" "http://localhost:8080/url2" [3] $ kill $(ps aux | grep [d]emo-tomcat-0.0.1-SNAPSHOT.jar | awk '{print $2}')
The request is not successful. Error 500 is returned.
Logs: app
2020-09-21 21:35:04.839 INFO 208159 --- [extShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown : Commencing graceful shutdown. Waiting for active requests to complete
2020-09-21 21:35:04.847 INFO 208159 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown : Graceful shutdown complete
2020-09-21 21:35:04.896 INFO 208159 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor : Shutting down ExecutorService 'applicationTaskExecutor'
curl
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /url2 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.68.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 500
< Content-Type: text/html;charset=utf-8
< Content-Language: en
< Content-Length: 455
< Date: Mon, 21 Sep 2020 19:35:04 GMT
< Connection: close
<
* Closing connection 0
<!doctype html><html lang="en"><head><title>HTTP Status 500 – Internal Server Error</title><style type="text/css">body {font-family:Tahoma,Arial,sans-serif;} h1, h2, h3, b {color:white;background-color:#525D76;} h1 {font-size:22px;} h2 {font-size:16px;} h3 {font-size:14px;} p {font-size:12px;} a {color:black;} .line {height:1px;background-color:#525D76;border:none;}</style></head><body><h1>HTTP Status 500 – Internal Server Error</h1></body></html>
Anything else we need to know?:
If you replace an embedded Tomcat server with an embedded Jetty or embedded undertow, the problem does not exist. I attach examples in the above mentioned repository.
Logs when used Jetty: app
2020-09-21 21:40:18.109 INFO 209508 --- [extShutdownHook] o.s.b.web.embedded.jetty.JettyWebServer : Commencing graceful shutdown. Waiting for active requests to complete
2020-09-21 21:40:35.531 INFO 209508 --- [ jetty-shutdown] o.s.b.web.embedded.jetty.JettyWebServer : Graceful shutdown complete
2020-09-21 21:40:35.535 INFO 209508 --- [extShutdownHook] o.e.jetty.server.AbstractConnector : Stopped ServerConnector@7b420819{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2020-09-21 21:40:35.536 INFO 209508 --- [extShutdownHook] org.eclipse.jetty.server.session : node0 Stopped scavenging
2020-09-21 21:40:35.538 INFO 209508 --- [extShutdownHook] o.e.j.s.h.ContextHandler.application : Destroying Spring FrameworkServlet 'dispatcherServlet'
2020-09-21 21:40:35.539 INFO 209508 --- [extShutdownHook] o.e.jetty.server.handler.ContextHandler : Stopped o.s.b.w.e.j.JettyEmbeddedWebAppContext@65045a87{application,/,[file:///tmp/jetty-docbase.4659637512004705994.8080/],UNAVAILABLE}
2020-09-21 21:40:35.541 INFO 209508 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor : Shutting down ExecutorService 'applicationTaskExecutor'
curl
* Re-using existing connection! (#0) with host localhost
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /url2 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.68.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Date: Mon, 21 Sep 2020 19:40:15 GMT
< Content-Type: text/plain;charset=utf-8
< Content-Length: 7
< Connection: close
<
* Closing connection 0
OK/url2
Environment: Spring Boot 2.3.4.RELEASE Apache Tomcat/9.0.38 Apache Maven 3.6.3 Java version: 11.0.8, vendor: AdoptOpenJDK, runtime: /usr/lib/jvm/adoptopenjdk-11-hotspot-amd64 Ubuntu 20.04.1 LTS (Focal Fossa), 5.4.0-47-generic, amd64
Comment From: wilkinsona
Thanks for the detailed problem report and sample. The problem doesn't appear to be due to keepalive but the counting of in-progress async requests. For each request, the in-progress count is incremented once but decremented twice. The stack trace of the first decrement is the following:
at org.apache.catalina.core.StandardContext.decrementInProgressAsyncCount(StandardContext.java:854)
at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:218)
at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:179)
at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:173)
at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:132)
at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:401)
at org.springframework.web.context.request.async.WebAsyncManager.lambda$startDeferredResultProcessing$8(WebAsyncManager.java:469)
at org.springframework.web.context.request.async.DeferredResult.setResultHandler(DeferredResult.java:223)
at org.springframework.web.context.request.async.WebAsyncManager.startDeferredResultProcessing(WebAsyncManager.java:467)
at org.springframework.web.servlet.mvc.method.annotation.DeferredResultMethodReturnValueHandler.handleReturnValue(DeferredResultMethodReturnValueHandler.java:75)
at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:82)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:123)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:878)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:792)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
For the same request, a second decrement is then performed:
at org.apache.catalina.core.StandardContext.decrementInProgressAsyncCount(StandardContext.java:854)
at org.apache.catalina.core.AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:116)
at org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:363)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:235)
at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:238)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.base/java.lang.Thread.run(Thread.java:834)
This leaves the in-progress count at -1. When you make a second request the in-progress account is incremented to 0. Graceful shutdown then checks for in-progress async requests, is told there are none, and proceeds with the shutdown rather than waiting for the request to complete.
I don't think Spring MVC is doing anything wrong in terms of calling dispatch which triggers the first decrement and the second is entirely within Tomcat's code. I think this may be a Tomcat bug.
@markt-asf could you please take a look?
Comment From: wilkinsona
The problem can be reproduced without keepalive by invoking curl twice:
$ curl -v "http://localhost:8080/url1"
$ curl -v "http://localhost:8080/url2"
When the server is killed while the second curl call is running, it will shut down immediately and the request fails with a 500.
Comment From: markt-asf
Agreed. This is a Tomcat bug, Working on it...
Comment From: markt-asf
Fixed for 10.0.x, 9.0.x and 8.5.x and will be in the next release of each (early next month - Oct '20).
Comment From: philwebb
We'll close this one and pick-up the Tomcat release that include https://github.com/apache/tomcat/commit/6d44f6aa52748df930f1563bb5598705eb75e1aa in due course.