Image building creates invalid image on consecutive runs

[dmurat]

Gradle command bootBuildImage creates an invalid image on every other run. I mean, the first run creates a correct image, but when bootBuildImage is executed again, the created image cannot be started.

Environment

Spring Boot 2.5.0, Gradle 7.0.2, osx, java 11

To reproduce:

First build and run

• on https://start.spring.io create a new packsbugjava app, and select Gradle project
• build the project with ./gradlew build
• create the image with ./gradlew bootBuildImage
• note the output of Paketo BellSoft Liberica Buildpack

[creator]     Paketo BellSoft Liberica Buildpack 8.1.0
    [creator]       https://github.com/paketo-buildpacks/bellsoft-liberica
    [creator]       Build Configuration:
    [creator]         $BP_JVM_VERSION              11.*            the Java version
    [creator]       Launch Configuration:
    [creator]         $BPL_JVM_HEAD_ROOM           0               the headroom in memory calculation
    [creator]         $BPL_JVM_LOADED_CLASS_COUNT  35% of classes  the number of loaded classes in memory calculation
    [creator]         $BPL_JVM_THREAD_COUNT        250             the number of threads in memory calculation
    [creator]         $JAVA_TOOL_OPTIONS                           the JVM launch flags
    [creator]       BellSoft Liberica JRE 11.0.11: Contributing to layer
    [creator]         Downloading from https://github.com/bell-sw/Liberica/releases/download/11.0.11+9/bellsoft-jre11.0.11+9-linux-amd64.tar.gz
    [creator]         Verifying checksum
    [creator]         Expanding to /layers/paketo-buildpacks_bellsoft-liberica/jre
    [creator]         Adding 129 container CA certificates to JVM truststore
    [creator]         Writing env.launch/BPI_APPLICATION_PATH.default
    [creator]         Writing env.launch/BPI_JVM_CACERTS.default
    [creator]         Writing env.launch/BPI_JVM_CLASS_COUNT.default
    [creator]         Writing env.launch/BPI_JVM_SECURITY_PROVIDERS.default
    [creator]         Writing env.launch/JAVA_HOME.default
    [creator]         Writing env.launch/MALLOC_ARENA_MAX.default
    [creator]       Launch Helper: Contributing to layer
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/active-processor-count
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/java-opts
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/link-local-dns
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/memory-calculator
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/openssl-certificate-loader
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/security-providers-configurer
    [creator]         Creating /layers/paketo-buildpacks_bellsoft-liberica/helper/exec.d/security-providers-classpath-9
    [creator]       JVMKill Agent 1.16.0: Contributing to layer
    [creator]         Downloading from https://github.com/cloudfoundry/jvmkill/releases/download/v1.16.0.RELEASE/jvmkill-1.16.0-RELEASE.so
    [creator]         Verifying checksum
    [creator]         Copying to /layers/paketo-buildpacks_bellsoft-liberica/jvmkill
    [creator]         Writing env.launch/JAVA_TOOL_OPTIONS.append
    [creator]         Writing env.launch/JAVA_TOOL_OPTIONS.delim
    [creator]       Java Security Properties: Contributing to layer
    [creator]         Writing env.launch/JAVA_SECURITY_PROPERTIES.default
    [creator]         Writing env.launch/JAVA_TOOL_OPTIONS.append
    [creator]         Writing env.launch/JAVA_TOOL_OPTIONS.delim

• run the image with docker run --rm packsbugjava:0.0.1-SNAPSHOT
• the image runs correctly with following output

Setting Active Processor Count to 6
Calculating JVM memory based on 7057336K available memory
Calculated JVM Memory Configuration: -XX:MaxDirectMemorySize=10M -Xmx6460274K -XX:MaxMetaspaceSize=85061K -XX:ReservedCodeCacheSize=240M -Xss1M (Total Memory: 7057336K, Thread Count: 250, Loaded Class Count: 12604, Headroom: 0%)
Adding 129 container CA certificates to JVM truststore
Spring Cloud Bindings Enabled
Picked up JAVA_TOOL_OPTIONS: -Djava.security.properties=/layers/paketo-buildpacks_bellsoft-liberica/java-security-properties/java-security.properties -agentpath:/layers/paketo-buildpacks_bellsoft-liberica/jvmkill/jvmkill-1.16.0-RELEASE.so=printHeapHistogram=1 -XX:ActiveProcessorCount=6 -XX:MaxDirectMemorySize=10M -Xmx6460274K -XX:MaxMetaspaceSize=85061K -XX:ReservedCodeCacheSize=240M -Xss1M -Dorg.springframework.cloud.bindings.boot.enable=true

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

2021-06-06 12:35:32.522  INFO 1 --- [           main] c.e.p.PacksbugjavaApplication            : Starting PacksbugjavaApplication using Java 11.0.11 on 074ec6024b54 with PID 1 (/workspace/BOOT-INF/classes started by cnb in /workspace)
2021-06-06 12:35:32.524  INFO 1 --- [           main] c.e.p.PacksbugjavaApplication            : No active profile set, falling back to default profiles: default
2021-06-06 12:35:33.396  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-06-06 12:35:33.406  INFO 1 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2021-06-06 12:35:33.406  INFO 1 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.46]
2021-06-06 12:35:33.451  INFO 1 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2021-06-06 12:35:33.451  INFO 1 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 875 ms
2021-06-06 12:35:33.919  INFO 1 --- [           main] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 1 endpoint(s) beneath base path '/actuator'
2021-06-06 12:35:33.953  INFO 1 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2021-06-06 12:35:33.965  INFO 1 --- [           main] c.e.p.PacksbugjavaApplication            : Started PacksbugjavaApplication in 1.861 seconds (JVM running for 2.141)
2021-06-06 12:35:34.004  INFO 1 --- [           main] o.s.b.a.ApplicationAvailabilityBean      : Application availability state LivenessState changed to CORRECT
2021-06-06 12:35:34.006  INFO 1 --- [           main] o.s.b.a.ApplicationAvailabilityBean      : Application availability state ReadinessState changed to ACCEPTING_TRAFFIC

Second build and run

• create the image with ./gradlew bootBuildImage
• note the output of Paketo BellSoft Liberica Buildpack

    [creator]     Paketo BellSoft Liberica Buildpack 8.1.0
    [creator]       https://github.com/paketo-buildpacks/bellsoft-liberica
    [creator]       Build Configuration:
    [creator]         $BP_JVM_VERSION              11.*            the Java version
    [creator]       Launch Configuration:
    [creator]         $BPL_JVM_HEAD_ROOM           0               the headroom in memory calculation
    [creator]         $BPL_JVM_LOADED_CLASS_COUNT  35% of classes  the number of loaded classes in memory calculation
    [creator]         $BPL_JVM_THREAD_COUNT        250             the number of threads in memory calculation
    [creator]         $JAVA_TOOL_OPTIONS                           the JVM launch flags
    [creator]       BellSoft Liberica JRE 11.0.11: Reusing cached layer
    [creator]       Launch Helper: Reusing cached layer
    [creator]       JVMKill Agent 1.16.0: Reusing cached layer
    [creator]       Java Security Properties: Reusing cached layer

• run the image with docker run --rm packsbugjava:0.0.1-SNAPSHOT
• the image can not start and produces the following error:

ERROR: failed to launch: path lookup: exec: "java": executable file not found in $PATH

If ones try to build an image again, output from the first run above will reapear, and the image will be runnable. Next image generation will again create the inavalid image, and so on. Every other generated image will be valid/invalid.

[scottfrederick]

Thanks for the report. I can re-create this problem with the steps you've provided.

I can also re-create the problem by running ./gradlew build and then the pack CLI command pack build pack-test --path ./build/libs/packsbugjava-0.0.1-SNAPSHOT.jar --builder paketobuildpacks/builder:base instead of ./gradlew bootBuildImage. The same error occurs when a Java buildpack other than Bellsoft Liberica is selected. This indicates that the root cause of the problem is likely in the Paketo builder's caching logic. I'm not sure which Paketo repository to report the problem in, so I'll make that team aware of the problem, let them open an issue to address it, and link to the issue here.

[pbilstein]

I had the same problem and was able to apply a workaround by setting

cleanCache = true in the bootBuildImage section of my build.gradle

Example:

bootBuildImage {
  imageName = "foo/bar"
  cleanCache = true
}

Of course this might slow down the builds and nevertheless should be fixed in paketo...

EDIT: typo

[scottfrederick]

The issue has been identified by the Paketo team, and a fix is working its way through their CI system. If you are using one of thepaketobuildpacks/builder builders then a new builder will be published to Docker Hub that fixes the problem.