How to properly configure Kubernetes probes timing (for Spring Boot Application)

10/8/2020

We have a simple Spring Boot web application which takes less than 30 seconds to start. So I configured the probes as follow:

    readinessProbe:
      httpGet:
        path: /actuator/health/readiness
        port: 8080
      initialDelaySeconds: 30
      periodSeconds: 1
    livenessProbe:
      httpGet:
        path: /actuator/health/liveness
        port: 8080
      initialDelaySeconds: 30
      periodSeconds: 1

My understanding is that readiness probe waits for 30 seconds and then will succeed (if the application is started). And also liveness probe with 30 seconds delay (from the beginning of the deployment) starts and will succeeds almost at the same time readiness probe succeeds (if the application is ready). But what I see in logs is that readiness probe waits for 30 seconds and then succeeds, but after that there's another 30 seconds waiting time and then the old pod gets shut down:

develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:07.378Z","logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","level":"INFO","thread":"main","message":"Tomcat started on port(s): 8080 (http) with context path ''"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:07.387Z","logger":"org.springframework.data.repository.config.DeferredRepositoryInitializationListener","level":"INFO","thread":"main","message":"Triggering deferred initialization of Spring Data repositories…"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:09.441Z","logger":"org.springframework.data.repository.config.DeferredRepositoryInitializationListener","level":"INFO","thread":"main","message":"Spring Data repositories initialized!"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:09.469Z","logger":"com.example.Application","level":"INFO","thread":"main","message":"Started Application in 23.918 seconds (JVM running for 25.343)"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:14.251Z","logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/]","level":"INFO","thread":"http-nio-8080-exec-1","message":"Initializing Spring DispatcherServlet 'dispatcherServlet'"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:14.258Z","logger":"org.springframework.web.servlet.DispatcherServlet","level":"INFO","thread":"http-nio-8080-exec-1","message":"Initializing Servlet 'dispatcherServlet'"}
develop/demo-57c8984866-6v5sl[demo]: {"ts":"2020-10-08T17:33:14.292Z","logger":"org.springframework.web.servlet.DispatcherServlet","level":"INFO","thread":"http-nio-8080-exec-1","message":"Completed initialization in 30 ms"}
develop/demo-79cc9bc757-xlg6z[demo]: 2020-10-08T17:33:44.590172 Shutting down...
develop/demo-79cc9bc757-xlg6z[demo]: {"ts":"2020-10-08T17:33:44.658Z","logger":"org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean","level":"INFO","thread":"SpringContextShutdownHook","message":"Closing JPA EntityManagerFactory for persistence unit 'default'"}
develop/demo-79cc9bc757-xlg6z[demo]: {"ts":"2020-10-08T17:33:44.664Z","logger":"org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor","level":"INFO","thread":"SpringContextShutdownHook","message":"Shutting down ExecutorService 'applicationTaskExecutor'"}
develop/demo-79cc9bc757-xlg6z[demo]: {"ts":"2020-10-08T17:33:44.667Z","logger":"com.zaxxer.hikari.HikariDataSource","level":"INFO","thread":"SpringContextShutdownHook","message":"HikariPool-1 - Shutdown initiated..."}
develop/demo-79cc9bc757-xlg6z[demo]: {"ts":"2020-10-08T17:33:44.680Z","logger":"com.zaxxer.hikari.HikariDataSource","level":"INFO","thread":"SpringContextShutdownHook","message":"HikariPool-1 - Shutdown completed."}

What's the reason for the 2nd 30-second waiting time (see the first "Shutting down...")? For the record, there's not SIGTERM problem (the application responds properly to SIGTERM).

MORE INFO
Correct me if I'm wrong about how these probes work: The container starts, at this moment the timer for readiness initial delay also starts. 25 sec later the app is ready. 5 more sec later, the readiness probe starts hitting the app/container and it succeeds, thus the app is ready (right?). At this point I expect k8s send the sigterm to the old pod, asking it to shut down. But as shown in the logs, after the new container is ready, the old pod is still running for 30 more sec.
Maybe, rephrasing the question helps. I'd like to shut down old pod right after the app is ready. And the app is ready in less than 30 sec. In other words I need the whole deployment to take only 30 sec (considering the startup is less than 30 sec and shutdown is less than one sec). Why the above configuration doesn't do that? Thanks.

-- Rad
amazon-eks
kubernetes
spring-boot

2 Answers

10/12/2020

OK, it turned out the tool (kubecfg) and library we use to manage our k8s manifests has a different default value for minReadySeconds property (30 seconds). I changed that and everything is working as expected.

-- Rad
Source: StackOverflow

10/8/2020

From your description you are doing everything alright.

What we observe is that a different pod is shutting down, than the one that first logged the startup information. Without more information this looks like a rolling update that waits to shutdown old pods until new pods become available and healthy.

You can tell by looking at the log messages: The pod name is in front of each line.

-- Thomas
Source: StackOverflow