The problem
We recently upgraded from spring boot 2.1.6.RELEASE to 2.3.1.RELEASE. After that we realized that the endpoint /ops/pause is not functioning any longer. Before it stopped two kafka consumers in our application. Now it seems to also shutdown the spring boot managed tomcat server. After the call we cannot get any requests working. The server refuses any connection after that but the application is still running (no exit codes in the log).
What we tried
- Reverting the
spring-cloud-framework,spring-boot-actuatorandspring-boot-starter-tomcatversion to2.1.6.RELEASE - Debugging
More info
Management related properties in our application.properties
management.health.status.order=DOWN, UP
management.endpoint.jolokia.enabled=true
management.endpoint.metrics.enabled=true
management.endpoint.pause.enabled=true
management.endpoint.resume.enabled=true
management.endpoint.restart.enabled=true
management.endpoints.web.exposure.include=*
management.endpoints.web.base-path=/ops
The log after calling /ops/pause
2020-07-13 11:55:15,347 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.coyote.http11.Http11NioProtocol - Pausing ProtocolHandler ["http-nio-31016"]
2020-07-13 11:55:15,355 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.catalina.core.StandardService - Stopping service [Tomcat]
2020-07-13 11:55:15,357 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.catalina.core.StandardWrapper - Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-13 11:55:16,363 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.catalina.core.StandardWrapper - Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-13 11:55:17,389 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.catalina.core.StandardWrapper - Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-13 11:55:17,493 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Destroying Spring FrameworkServlet 'dispatcherServlet'
2020-07-13 11:55:17,500 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.coyote.http11.Http11NioProtocol - Stopping ProtocolHandler ["http-nio-31016"]
2020-07-13 11:55:17,503 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 WARN o.apache.tomcat.util.net.NioEndpoint - The executor associated with thread pool [http-nio-31016] has not fully shutdown. Some application threads may still be running.
2020-07-13 11:55:17,504 [http-nio-31016-exec-2] traceId=3b2fc7d64f4e0d82 spanId=3b2fc7d64f4e0d82 INFO o.a.coyote.http11.Http11NioProtocol - Destroying ProtocolHandler ["http-nio-31016"]
2020-07-13 11:55:17,542 [http-nio-31016-exec-2] traceId= spanId= ERROR o.a.c.c.C.[.[.[.[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception
java.lang.NullPointerException: null
at java.base/java.util.Objects.requireNonNull(Objects.java:221)
at io.micrometer.core.instrument.ImmutableTag.<init>(ImmutableTag.java:35)
at io.micrometer.core.instrument.Tag.of(Tag.java:29)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcTags.method(WebMvcTags.java:74)
at org.springframework.boot.actuate.metrics.web.servlet.DefaultWebMvcTagsProvider.getTags(DefaultWebMvcTagsProvider.java:74)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.getTimer(WebMvcMetricsFilter.java:169)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.record(WebMvcMetricsFilter.java:129)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:105)
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:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373)
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)
2020-07-13 11:55:17,546 [http-nio-31016-exec-2] traceId= spanId= ERROR o.a.coyote.http11.Http11Processor - Error processing request
java.lang.NullPointerException: null
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:412)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373)
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)
2020-07-13 11:55:17,547 [http-nio-31016-exec-2] traceId= spanId= WARN o.a.catalina.connector.CoyoteAdapter - Exception while attempting to add an entry to the access log
java.lang.NullPointerException: null
at org.apache.catalina.connector.CoyoteAdapter.log(CoyoteAdapter.java:490)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:403)
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)
Comment From: wilkinsona
Thanks for the report. I suspect that this is due to a change to the way that the web server's lifecycle is managed in Spring Boot 2.3. The web server is now managed via a SmartLifecycle bean in the Integer.MAX_VALUE - 1 phase. The pause endpoint is part of Spring Cloud rather than Spring Boot itself. It is assuming that it can safely stop all smart lifecycle beans in all phases to pause an application. Unfortunately, that isn't a safe assumption to have made, particularly now that it affects the web server.
Can you please open a Spring Cloud Commons issue for this as changes will be required there. If changes are also needed in Spring Boot we can re-open this issue.
Comment From: moritzluedtke
@wilkinsona thank your for your fast response and background information!
As suggested I created an issue in the Spring Cloud Commons project: https://github.com/spring-cloud/spring-cloud-commons/issues/788