An active request delays Jetty's shutdown by 30 seconds

[ikilledmypc]

When using jetty with the new graceful shutdown feature in spring boot 2.3.2 the jetty waits indefinitly after the timeout has expired till all of the existing requests are finished.

I have created a small example application to reproduce.
graceful-shutdown.zip
Steps to reproduce:

• Start application
• Send get request to http://localhost:8080/test the thread will be blocked for 40 seconds
• While the request is running, shutdown the application by issuing a signal 15 initiating the gracefull shutdown
  If graceful shutdown config is correct it should wait for the timeout (10 seconds) and then drop any remaining requests (This works fine in Tomcat). However the logs notify gracefull shutdown has failed after the 10 second timeout and the application continues to wait for the remaining of the 40 seconds of the request to finish before shutting down.

logs:

2020-07-31 13:44:42.049  INFO 265866 --- [           main] o.s.b.web.embedded.jetty.JettyWebServer  : Jetty started on port(s) 8080 (http/1.1) with context path '/'
2020-07-31 13:44:42.059  INFO 265866 --- [           main] c.e.g.GracefulShutdownApplication        : Started GracefulShutdownApplication in 0.843 seconds (JVM running for 1.189)
2020-07-31 13:46:08.965  INFO 265866 --- [extShutdownHook] o.s.b.web.embedded.jetty.JettyWebServer  : Commencing graceful shutdown. Waiting for active requests to complete
2020-07-31 13:46:18.969  INFO 265866 --- [extShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Failed to shut down 1 bean with phase value 2147483647 within timeout of 10000ms: [webServerGracefulShutdown]
2020-07-31 13:46:18.987  INFO 265866 --- [ jetty-shutdown] o.s.b.web.embedded.jetty.JettyWebServer  : Graceful shutdown aborted with 1 request(s) still active
2020-07-31 13:46:44.905  INFO 265866 --- [extShutdownHook] o.e.jetty.server.AbstractConnector       : Stopped ServerConnector@257cc1fc{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2020-07-31 13:46:44.905  INFO 265866 --- [extShutdownHook] org.eclipse.jetty.server.session         : node0 Stopped scavenging
2020-07-31 13:46:44.906  INFO 265866 --- [extShutdownHook] o.e.j.s.h.ContextHandler.application     : Destroying Spring FrameworkServlet 'dispatcherServlet'
2020-07-31 13:46:44.907  INFO 265866 --- [extShutdownHook] o.e.jetty.server.handler.ContextHandler  : Stopped o.s.b.w.e.j.JettyEmbeddedWebAppContext@5b275174{application,/,[file:///tmp/jetty-docbase.13980908866127647764.8080/],UNAVAILABLE}
2020-07-31 13:46:44.908  INFO 265866 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
Process finished with exit code 143 (interrupted by signal 15: SIGTERM)

[wilkinsona]

Thanks for the report and sample project. The application isn't shutting down when it should as Jetty's QueuedThreadPool is waiting for 30 seconds for all of its threads to become idle. This occurs with both immediate and graceful shutdown. You can work around the problem by setting the Jetty Server's stop timeout to zero:

@Bean
public JettyServerCustomizer jettyServerCustomizer() {
	return (server) -> server.setStopTimeout(0);
}

[ikilledmypc]

@wilkinsona Thanks so much for the swift reply and solution I just tested it in our app and it seems to work!

[jhoglin]

I see the exact same behaviour using webflux and netty. Springboot version 2.3.2.

13:03:00.334 [reactor-http-nio-2] INFO  com.example.HelloResource - ------------------ Sleeping for 60 sec
13:03:02.590 [SpringContextShutdownHook] INFO  org.springframework.boot.web.embedded.netty.GracefulShutdown - Commencing graceful shutdown. Waiting for active requests to complete
13:03:12.592 [SpringContextShutdownHook] INFO  org.springframework.context.support.DefaultLifecycleProcessor - Failed to shut down 1 bean with phase value 2147483647 within timeout of 10000ms: [webServerGracefulShutdown]
13:03:12.613 [netty-shutdown] INFO  org.springframework.boot.web.embedded.netty.GracefulShutdown - Graceful shutdown aborted with one or more requests still active

After 60 seconds the request completes, I get a 200 in the browser and the process exits with exit code 130.

The design is that after the grace period to kill any requests and shut down the process right?

Hope this helps.

[wilkinsona]

@jhoglin Thanks. That's a known (and separate) issue. Please see #21426 for details.