Search code examples
javaspring-bootdockerhibernateazure-container-apps

Spring Boot application shutting down immediately after start


I can't figure out why my dockerized Spring Boot application terminates immediately after starting up. I looked into similar issues but couldn't find a reason for mine to fail yet.

The docker image runs ok locally, but when running on Azure Container Apps it does an auto-shutdown.

This is the log with Hikari on debug:

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

2022-10-02 23:09:00.444  INFO 1 --- [           main] io.pomatti.app.books.BookApplication     : Starting BookApplication v0.0.1-SNAPSHOT using Java 17.0.4.1 on app-books--sw6babs-6db8f449fb-n2pvt with PID 1 (/opt/app/*.jar started by root in /opt/app)
2022-10-02 23:09:00.509  INFO 1 --- [           main] io.pomatti.app.books.BookApplication     : No active profile set, falling back to 1 default profile: "default"
2022-10-02 23:09:02.933  INFO 1 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2022-10-02 23:09:03.111  INFO 1 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 169 ms. Found 1 JPA repository interfaces.
2022-10-02 23:09:04.535  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2022-10-02 23:09:04.542  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-10-02 23:09:04.542  INFO 1 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.65]
2022-10-02 23:09:04.715  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-10-02 23:09:04.715  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 4080 ms
2022-10-02 23:09:04.927 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : Driver class com.microsoft.sqlserver.jdbc.SQLServerDriver found in Thread context class loader TomcatEmbeddedWebappClassLoader
  context: ROOT
  delegate: true
----------> Parent Classloader:
org.springframework.boot.loader.LaunchedURLClassLoader@28c97a5

2022-10-02 23:09:05.833  INFO 1 --- [           main] o.hibernate.jpa.internal.util.LogHelper  : HHH000204: Processing PersistenceUnitInfo [name: default]
2022-10-02 23:09:06.014  INFO 1 --- [           main] org.hibernate.Version                    : HHH000412: Hibernate ORM core version 5.6.11.Final
2022-10-02 23:09:06.327  INFO 1 --- [           main] o.hibernate.annotations.common.Version   : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2022-10-02 23:09:06.617 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : HikariPool-1 - configuration:
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : allowPoolSuspension................................false
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : autoCommit................................true
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : catalog................................none
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : connectionInitSql................................none
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : connectionTestQuery................................none
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : connectionTimeout................................30000
2022-10-02 23:09:06.620 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : dataSource................................none
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : dataSourceClassName................................none
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : dataSourceJNDI................................none
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : dataSourceProperties................................{password=<masked>}
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : driverClassName................................"com.microsoft.sqlserver.jdbc.SQLServerDriver"
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : exceptionOverrideClassName................................none
2022-10-02 23:09:06.621 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : healthCheckProperties................................{}
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : healthCheckRegistry................................none
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : idleTimeout................................600000
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : initializationFailTimeout................................1
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : isolateInternalQueries................................false
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : jdbcUrl................................jdbc:sqlserver://sql-autoscale-2996.database.windows.net:1433;database=sqldb-autoscale-2996;user=dbadmin@sql-autoscale-2996;password=<masked>#777;encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;loginTimeout=30;
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : keepaliveTime................................0
2022-10-02 23:09:06.622 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : leakDetectionThreshold................................0
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : maxLifetime................................1800000
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : maximumPoolSize................................10
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : metricRegistry................................none
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : metricsTrackerFactory................................com.zaxxer.hikari.metrics.micrometer.MicrometerMetricsTrackerFactory@5e8a459
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : minimumIdle................................10
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : password................................<masked>
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : poolName................................"HikariPool-1"
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : readOnly................................false
2022-10-02 23:09:06.623 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : registerMbeans................................false
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : scheduledExecutor................................none
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : schema................................none
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : threadFactory................................internal
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : transactionIsolation................................default
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : username................................none
2022-10-02 23:09:06.624 DEBUG 1 --- [           main] com.zaxxer.hikari.HikariConfig           : validationTimeout................................5000
2022-10-02 23:09:06.624  INFO 1 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2022-10-02 23:09:07.726 DEBUG 1 --- [           main] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:1 ClientConnectionId: 1061c2f8-febf-4f1f-b9f6-86ee6dd22af4
2022-10-02 23:09:07.732  INFO 1 --- [           main] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.
2022-10-02 23:09:07.824  INFO 1 --- [           main] org.hibernate.dialect.Dialect            : HHH000400: Using dialect: org.hibernate.dialect.SQLServer2012Dialect
2022-10-02 23:09:07.832 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=1, active=1, idle=0, waiting=0)
2022-10-02 23:09:08.027 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:2 ClientConnectionId: 5035df48-1a77-406f-95b1-99d289e2d70e
2022-10-02 23:09:08.227 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:3 ClientConnectionId: 2f01f8bb-e542-4351-9b5c-dcf7cd6084ef
2022-10-02 23:09:08.411 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:4 ClientConnectionId: fd8950e7-85e8-4ae2-80be-8d88d3a7c84d
2022-10-02 23:09:08.614 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:5 ClientConnectionId: 73205252-2e69-4a7d-b347-9ba7d8e6458f
2022-10-02 23:09:08.737 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:6 ClientConnectionId: 0814ccbd-f55c-4442-925d-be9046619eb5
2022-10-02 23:09:08.921 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:7 ClientConnectionId: f5fb5f48-1c99-4b0c-9b58-828627cfaac2
2022-10-02 23:09:09.119 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:8 ClientConnectionId: 730e1bf3-1e7b-4416-980e-9a64cda711ea
2022-10-02 23:09:09.319 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:9 ClientConnectionId: 23786119-d561-4da6-a59e-08ceb76c7065
2022-10-02 23:09:09.519 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection ConnectionID:10 ClientConnectionId: 9cc6c870-b6a2-4ee3-bc06-14d81bd03471
2022-10-02 23:09:09.519 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0)
2022-10-02 23:09:09.826  INFO 1 --- [           main] o.h.e.t.j.p.i.JtaPlatformInitiator       : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2022-10-02 23:09:09.832  INFO 1 --- [           main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2022-10-02 23:09:10.419  WARN 1 --- [           main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2022-10-02 23:09:11.224  INFO 1 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2022-10-02 23:09:11.314  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2022-10-02 23:09:11.325  INFO 1 --- [           main] io.pomatti.app.books.BookApplication     : Started BookApplication in 11.913 seconds (JVM running for 12.911)
2022-10-02 23:09:11.412  INFO 1 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2022-10-02 23:09:11.415  INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2022-10-02 23:09:11.415 DEBUG 1 --- [ionShutdownHook] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Before shutdown stats (total=10, active=0, idle=10, waiting=0)
2022-10-02 23:09:11.416 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:1 ClientConnectionId: 1061c2f8-febf-4f1f-b9f6-86ee6dd22af4: (connection evicted)
2022-10-02 23:09:11.416 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:2 ClientConnectionId: 5035df48-1a77-406f-95b1-99d289e2d70e: (connection evicted)
2022-10-02 23:09:11.417 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:3 ClientConnectionId: 2f01f8bb-e542-4351-9b5c-dcf7cd6084ef: (connection evicted)
2022-10-02 23:09:11.417 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:4 ClientConnectionId: fd8950e7-85e8-4ae2-80be-8d88d3a7c84d: (connection evicted)
2022-10-02 23:09:11.418 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:5 ClientConnectionId: 73205252-2e69-4a7d-b347-9ba7d8e6458f: (connection evicted)
2022-10-02 23:09:11.418 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:6 ClientConnectionId: 0814ccbd-f55c-4442-925d-be9046619eb5: (connection evicted)
2022-10-02 23:09:11.419 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:7 ClientConnectionId: f5fb5f48-1c99-4b0c-9b58-828627cfaac2: (connection evicted)
2022-10-02 23:09:11.419 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:8 ClientConnectionId: 730e1bf3-1e7b-4416-980e-9a64cda711ea: (connection evicted)
2022-10-02 23:09:11.420 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:9 ClientConnectionId: 23786119-d561-4da6-a59e-08ceb76c7065: (connection evicted)
2022-10-02 23:09:11.420 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection ConnectionID:10 ClientConnectionId: 9cc6c870-b6a2-4ee3-bc06-14d81bd03471: (connection evicted)
2022-10-02 23:09:11.421 DEBUG 1 --- [ionShutdownHook] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - After shutdown stats (total=0, active=0, idle=0, waiting=0)
2022-10-02 23:09:11.421  INFO 1 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

My pom.xml:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.7.4</version>
        <relativePath /> <!-- lookup parent from repository -->
    </parent>
    <groupId>io.pomatti.app</groupId>
    <artifactId>order</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <name>order</name>
    <description>Demo project for Spring Boot</description>

    <properties>
        <java.version>17</java.version>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>

    <dependencies>
        <!-- Spring -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-data-jpa</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>

        <dependency>
            <groupId>com.microsoft.sqlserver</groupId>
            <artifactId>mssql-jdbc</artifactId>
            <version>11.2.1.jre17</version>
        </dependency>

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.18.24</version>
            <scope>provided</scope>
        </dependency>

    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

Main class:

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
@RequestMapping("/api/books")
public class BookApplication {

    public static void main(String[] args) {
        SpringApplication.run(BookApplication.class, args);
    }

    @Autowired
    BookRepository repository;

    @PostMapping("/")
    public Book post(@RequestBody Book order) {
        var book = new Book();
        book.setName("Eternal Sunshine");
        book.setAuthor("Anonymous");
        return repository.save(book);
    }

}

Dockerfile:

# syntax=docker/dockerfile:1

FROM eclipse-temurin:17-jdk-jammy as builder
WORKDIR /opt/app
COPY .mvn/ .mvn
COPY mvnw pom.xml ./
RUN ./mvnw dependency:go-offline
COPY ./src ./src
RUN ./mvnw clean install
 
 
FROM eclipse-temurin:17-jre-jammy
WORKDIR /opt/app
EXPOSE 8080
COPY --from=builder /opt/app/target/*.jar /opt/app/*.jar
ENTRYPOINT ["java", "-jar", "/opt/app/*.jar" ]

Solution

  • Pods were being restarted due to a too short initial delay for the health probe, which I had set for 3s. I've increased it to 10s and it solved the issue.

    probes = [
      {
        type = "Liveness"
        httpGet = {
          path = "/actuator/health"
          port = var.ingress_target_port
          httpHeaders = [
            {
              name  = "Custom-Header"
              value = "Awesome"
            }
          ]
        }
        initialDelaySeconds = 10
        periodSeconds       = 5
      }
    ]
    

    I've found that out by looking into the System Logs available for each container.

    enter image description here