Major Description
General Description :
Issue happens on all our Springboot (tomcat) + CXF app.
Spring boot version : 2.4.13 (same on 2.6.7) / CXF version : 3.5.1 (same on 3.4.4, 3.5.2)
Java 1.8.0_312 and Java 11.0.15
Integration is done with org.apache.cxf.cxf-spring-boot-starter-jaxrs-3.5.1.jar and org.apache.cxf.cxf-spring-boot-autoconfigure-3.5.1.jar
On each graceful shutdown that is happening under a moderate load, a few requests are being rejected in 404 by the service.
The corresponding log is "Can't find the request for XXXXX's Observer" XXXXX is the full request that has been rejected.
The http response body answer for the call is <html><body>No service was found.</body></html>
Integration :
CXF server is started like this :
@Bean
public Server flowManagementServiceRsServer() {
final JAXRSServerFactoryBean endpoint = new JAXRSServerFactoryBean();
endpoint.setBus(bus);
endpoint.setAddress("/");
endpoint.setServiceBean(new Service());
return endpoint.create();
}
Shutdown is managed by spring boot with "new" graceful shutdown server.shutdown=graceful and spring.lifecycle.timeout-per-shutdown-phase=25s
Reproduction :
Having a performance test on an endpoint (for example http://localhost:8080/services/request) and stopping gracefully, the app allow to reproduce the issue at will.
See cxf-shutdown.zip project to reproduce.
Use the following command just before trying to shutdown :
seq 1 2000 | xargs -I $ -n1 -P10 curl [http://127.0.0.1:8080/services/request]
Or see the JMeter project to do the same.
Logs and trace :
. ____ _ __ _ _
/
/ __{_}'{_} __ _ {_}({_})_ __ __ _ \ \ \ \
( ( )___ | '_ | '{_}| | '{_} \/ _` | \ \ \ \
/ __{_})| |{_})| | | | | || (_| | ) ) ) )
' |___{_}| .{_}{_}|{_}| |{_}|{_}| |{_}_{_}, | / / / /
=========|{_}|==============|{_}_{_}/=/{_}/{_}/{_}/
:: Spring Boot :: (v2.6.7)
2022-05-09 18:00:05.456 INFO 706858 — [ main] org.example.Application : Starting Application using Java 11.0.15 on LT-XXX with PID 706858 (/home/user/workspace/git/cxf-shutdown/target/classes started by user in /home/user/workspace/git/cxf-shutdown)
2022-05-09 18:00:05.459 INFO 706858 — [ main] org.example.Application : No active profile set, falling back to 1 default profile: "default"
2022-05-09 18:00:06.719 INFO 706858 — [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2022-05-09 18:00:06.728 INFO 706858 — [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2022-05-09 18:00:06.729 INFO 706858 — [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.62]
2022-05-09 18:00:06.795 INFO 706858 — [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-05-09 18:00:06.795 INFO 706858 — [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1285 ms
2022-05-09 18:00:07.042 INFO 706858 — [ main] org.apache.cxf.endpoint.ServerImpl : Setting the server's publish address to be /
2022-05-09 18:00:07.400 INFO 706858 — [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2022-05-09 18:00:07.444 INFO 706858 — [ main] org.example.Application : Started Application in 2.393 seconds (JVM running for 3.103)
2022-05-09 18:00:18.867 INFO 706858 — [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown : Commencing graceful shutdown. Waiting for active requests to complete
2022-05-09 18:00:18.867 WARN 706858 — [io-8080-exec-10] o.a.c.t.servlet.ServletController : Can't find the request for [http://127.0.0.1:8080/services/request's] Observer
2022-05-09 18:00:18.873 INFO 706858 — [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown : Graceful shutdown complete
Process finished with exit code 130 (interrupted by signal 2: SIGINT)