Failures caused by using buildpacks to create a native image without declaring the native build tools Maven plugin are hard to diagnose

[ah1508]

Following up on the last messages of this issue #32659 , I cannot use HikariCP with native image.

I tried to narrow the problem as much as possible so this example is a demo application created with start.spring.io, with only HikariCP and H2 as dependencies. Not even spring-jdbc so auto configuration will not apply, Datasource is created with a @Bean method.

new HikariDataSource() works, pool initialization does not (first call to datasource.getConnection() does not).

The project

Steps to reproduce the problem:

mvn clean spring-boot:build-image -Pnative
docker run -p8080:8080 demo-spring:0.0.1-SNAPSHOT
curl http://localhost:8080/hikari

curl http://localhost:8080/hikari leads to

Connection conn = datasource.getConnection();

which does not work. The stacktrace

curl http://localhost:8080/direct leads to:

Connection conn = DriverManager.getConnection ("jdbc:h2:mem:demo");

which works.

Stacktrace also shows logback problems.

OS: ubuntu 22.10, docker: 20.10.21, Maven: 3.8.6, Java: 17.0.5

[wilkinsona]

Thanks for the sample. I've reproduced the problem when building the app using spring-boot:build-image. Interestingly, the problem does not occur when building the app directly with mvn -Pnative native:compile. It then starts (on macOS) with no logging problems:

$ target/demo-spring 

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

2022-11-29T18:02:22.683Z  INFO 76093 --- [           main] com.example.demo.DemoApplication         : Starting AOT-processed DemoApplication using Java 17.0.5 with PID 76093 (/Users/awilkinson/Downloads/demo-3/target/demo-spring started by awilkinson in /Users/awilkinson/Downloads/demo-3)
2022-11-29T18:02:22.683Z  INFO 76093 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to 1 default profile: "default"
2022-11-29T18:02:22.697Z  INFO 76093 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2022-11-29T18:02:22.697Z  INFO 76093 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-11-29T18:02:22.698Z  INFO 76093 --- [           main] o.apache.catalina.core.StandardEngine    : Starting Servlet engine: [Apache Tomcat/10.1.1]
2022-11-29T18:02:22.705Z  INFO 76093 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-11-29T18:02:22.705Z  INFO 76093 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 22 ms
2022-11-29T18:02:22.723Z  INFO 76093 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2022-11-29T18:02:22.723Z  INFO 76093 --- [           main] com.example.demo.DemoApplication         : Started DemoApplication in 0.049 seconds (process running for 0.064)
2022-11-29T18:02:45.133Z  INFO 76093 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-11-29T18:02:45.133Z  INFO 76093 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-11-29T18:02:45.134Z  INFO 76093 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

Making a request to http://localhost:8080/hikari succeeds with a 200 response and Hikari starts up successfully:

2022-11-29T18:02:45.134Z  INFO 76093 --- [nio-8080-exec-1] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2022-11-29T18:02:45.138Z  INFO 76093 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection conn0: url=jdbc:h2:mem:demo user=
2022-11-29T18:02:45.138Z  INFO 76093 --- [nio-8080-exec-1] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Start completed.

@ah1508 Assuming that you have a local GraalVM installation, what behaviour do you see if you build the app using mvn -Pnative native:compile?

[ah1508]

Indeed, it works with mvn -Pnative native:compile (GraalVM 22.3.0) and then ./demo-spring. Log message are also property displayed.

[mhalbritter]

This looks like that reachability metadata is missing in the image built by the buildpacks.

[wilkinsona]

Yeah, that's was it. Thanks, @mhalbritter.

The reachability metadata is missing because there's no plugin declaration in the pom file for org.graalvm.buildtools:native-maven-plugin. Adding one fixes the problem.

While we do document the need to declare both Boot's plugin and Graal's plugin, I think we should try to improve the diagnostics here. It's harder than it should be to figure out what's gone wrong when only Boot's plugin is declared. We could log a warning or perhaps even fail fast.

[ah1508]

indeed, it works with native-maven-plugin.

It was in the plugin documentation, but how about updating the requiremenents here: https://docs.spring.io/spring-boot/docs/3.0.0/reference/htmlsingle/#native-image.developing-your-first-application.buildpacks For the time being, This means you can just type a single command and quickly get a sensible image into your locally running Docker daemon is a bit misleading.

The plugin could also be added in the pom.xml generated by start.spring.io. Like spring-boot-maven-plugin. It could be commented, or added on condition ("native build" checkbox on the form).

[mhalbritter]

it is included when selecting the GraalVM feature in start.spring.io.

Gradle:

plugins {
  id 'java'
  id 'org.springframework.boot' version '3.0.0'
  id 'io.spring.dependency-management' version '1.1.0'
  id 'org.graalvm.buildtools.native' version '0.9.18'
}

Maven:

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

The section in the documentation assumes that you have created your project with start.spring.io:

The easiest way to start a new native Spring Boot project is to go to start.spring.io, add the “GraalVM Native Support” dependency and generate the project. The included HELP.md file will provide getting started hints.

[wilkinsona]

I'm not sure that it does make that assumption. It says "you should ensure that your pom.xml file uses the spring-boot-starter-parent". start.spring.io always uses the parent so there would be no need to mention it if we were working on the assumption that start.spring.io had been used to generate the project.

I think we should mention the need to declare the native-maven-plugin as we do in the equivalent section for Gradle. I've opened #33422 for that.