Spring Boot Actuator endpoint /pause shuts Tomcat application server down

[moritzluedtke]

Describe the bug
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).

Sample
Don't have one right now but I can create a sample project if it helps.

Workaround
Revert back to 2.1.6.RELEASE as we do not need any of the new features or bug fixes.

More info

• Java 11
• Spring Boot 2.3.1.RELEASE

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)

[moritzluedtke]

A colleague of mine found out that in the method DefaultLifecycleProcessor#getLifecycleBeans() all beans are collected which will be shut down. If you call the mentioned actuator endpoint the list of beans is the following for us:

• documentationPluginsBootstrapper
• org.springframework.kafka.config.internalKafkaListenerEndpointRegistry
• webServerGracefulShutdown
• webServerStartStop

[ryanjbaxter]

Would you mind creating a sample app so we can take a look?

[moritzluedtke]

Sure, no problem:
https://github.com/moritzluedtke/spring-actuator-problem

I could not reproduce the NPE. We assume that the service wanted to write something to the logs but the tomcat was already in shut down mode and the log was no longer available. When it worked, the service logged that the Kafka consumers were stopped. So that is probably the message it wants to log and I don't have any Kafka integration in the sample project.

But you can see how the /pause command takes down the tomcat and the application.

We also did a bunch of testing and found out that this started to happen with spring boot version 2.3.0.RELEASE. The spring-cloud-dependencies did not seem to affect this issue as it appears in both Greenwich.SR2 and Hoxton.SR6.

Edit:
I did ask this question over in the spring boot project but was forwarded to you.
(spring-projects/spring-boot#22315)

This is the log with the sample project (at timestamp 09:25:48.261 I called /pause):

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.3.1.RELEASE)

2020-07-16 09:25:21.037  INFO [test,,,] 3722 --- [           main] c.e.a.ActuatorDemoApplication            : The following profiles are active: dev
2020-07-16 09:25:21.629  INFO [test,,,] 3722 --- [           main] o.s.cloud.context.scope.GenericScope     : BeanFactory id=e161ade0-a617-396f-acad-a3e1e19f088a
2020-07-16 09:25:21.812  INFO [test,,,] 3722 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$fcea6e0d] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-07-16 09:25:22.020  INFO [test,,,] 3722 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8001 (http)
2020-07-16 09:25:22.026  INFO [test,,,] 3722 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2020-07-16 09:25:22.026  INFO [test,,,] 3722 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.36]
2020-07-16 09:25:22.091  INFO [test,,,] 3722 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2020-07-16 09:25:22.091  INFO [test,,,] 3722 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1045 ms
2020-07-16 09:25:22.769  INFO [test,,,] 3722 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2020-07-16 09:25:23.112  INFO [test,,,] 3722 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 18 endpoint(s) beneath base path '/ops'
2020-07-16 09:25:23.199  INFO [test,,,] 3722 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8001 (http) with context path ''
2020-07-16 09:25:23.214  INFO [test,,,] 3722 --- [           main] c.e.a.ActuatorDemoApplication            : Started ActuatorDemoApplication in 2.662 seconds (JVM running for 3.494)
2020-07-16 09:25:23.425  INFO [test,,,] 3722 --- [on(2)-127.0.0.1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2020-07-16 09:25:23.425  INFO [test,,,] 3722 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2020-07-16 09:25:23.435  INFO [test,,,] 3722 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 10 ms
2020-07-16 09:25:48.261  INFO [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2020-07-16 09:25:48.262  INFO [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] o.apache.catalina.core.StandardWrapper   : Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-16 09:25:49.300  INFO [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] o.apache.catalina.core.StandardWrapper   : Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-16 09:25:50.330  INFO [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] o.apache.catalina.core.StandardWrapper   : Waiting for [1] instance(s) to be deallocated for Servlet [dispatcherServlet]
2020-07-16 09:25:50.433  INFO [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Destroying Spring FrameworkServlet 'dispatcherServlet'
2020-07-16 09:25:50.440  WARN [test,f5391faceb6c39e0,f5391faceb6c39e0,false] 3722 --- [nio-8001-exec-2] org.apache.tomcat.util.net.NioEndpoint   : The executor associated with thread pool [http-nio-8001] has not fully shutdown. Some application threads may still be running.
2020-07-16 09:25:50.444  INFO [test,,,] 3722 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'

Process finished with exit code 0

[moritzluedtke]

Did anyone had a chance to take a look at this?

[moritzluedtke]

This behaviour is still present in spring-boot 2.3.3.

[olagache]

Same issue for me.
Calling /actuator/pause return no awswer. Connection is closed before ...

curl -i -X POST    -H "Authorization:Bearer xxxxxxx"  'http://localhost:48880/actuator/pause'
--> curl: (52) Empty reply from server

Unable to call resume ,info or health after pause

curl -i -X POST    -H "Authorization:Bearer xxxxxxx"  'http://localhost:48880/actuator/resume'
--> curl: (7) Failed to connect to localhost port 48880: Connexion refusée

In discovery application, the paused service is marked as down and the PID (with ps command) is present.

[olagache]

@moritzluedtke : No news ?