Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AppCDS Archive Generation with quarkus-container-image-jib causes a timestamp mismatch #38057

Closed
davidreis97 opened this issue Jan 5, 2024 · 16 comments
Labels
area/container-image kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant

Comments

@davidreis97
Copy link

davidreis97 commented Jan 5, 2024

Describe the bug

When creating an AppCDS Archive with container image generation through the quarkus-container-image-jib extension, the following Docker command gets executed:

docker run -v /Users/my-user/repos/my-service/target:/tmp/quarkus:z -w /tmp/quarkus/quarkus-app --rm registry.access.redhat.com/ubi8/openjdk-21-runtime:1.18 java -XX:ArchiveClassesAtExit=app-cds.jsa -Dquarkus.appcds.generate=true -jar quarkus-run.jar

This command mounts the /target folder as a volume, which contains the library folders /quarkus-app/lib/boot and /quarkus-app/lib/main. This means that the AppCDS archive will be generated with the .jar files that are inside these two folders.

The issue is that after the AppCDS archive generation process, in the quarkus-container-image-jib image generation, the .jar files inside the /quarkus-app/lib/boot and /quarkus-app/lib/main folders are copied into the image in a way that causes their timestamp to change. See quarkusio/quarkus/extensions/container-image/container-image-jib/deployment/src/main/java/io/quarkus/container/image/jib/deployment/JibProcessor.java to see how this is done.

As an example, when building the AppCDS, these are the files inside the /lib/boot folder:

Screenshot 2024-01-05 at 10 55 23

And these are the files inside the final container:

Screenshot 2024-01-05 at 10 55 14

As you can see, the timestamps are different, which causes the error when CDS tries to load up the archive:

Picked up JAVA_TOOL_OPTIONS: -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=*:5005 -Dio.netty.leakDetection.level=paranoid -Xlog:class+path=info

[0.002s][info][class,path] bootstrap loader class path=/usr/lib/jvm/java-21-openjdk-21.0.1.0.12-3.el8.x86_64/lib/modules
[0.008s][info][class,path] Expecting BOOT path=/usr/lib/jvm/java-21-openjdk-21.0.1.0.12-3.el8.x86_64/lib/modules
[0.008s][info][class,path] Expecting -Djava.class.path=
[0.008s][info][class,path] checking shared classpath entry: /usr/lib/jvm/java-21-openjdk-21.0.1.0.12-3.el8.x86_64/lib/modules
[0.008s][info][class,path] ok
[0.022s][info][class,path] Expecting BOOT path=/usr/lib/jvm/java-21-openjdk-21.0.1.0.12-3.el8.x86_64/lib/modules
[0.022s][info][class,path] Expecting -Djava.class.path=quarkus-run.jar:lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar:lib/boot/io.smallrye.common.smallrye-common-os-2.1.2.jar:lib/boot/io.quarkus.quarkus-development-mode-spi-3.6.3.jar:lib/boot/io.quarkus.quarkus-bootstrap-runner-3.6.3.jar:lib/boot/io.smallrye.common.smallrye-common-io-2.1.2.jar:lib/boot/io.quarkus.quarkus-vertx-latebound-mdc-provider-3.6.3.jar:lib/boot/io.github.crac.org-crac-0.1.3.jar:lib/boot/org.jboss.logmanager.jboss-logmanager-3.0.2.Final.jar:lib/boot/io.smallrye.common.smallrye-common-constraint-2.1.2.jar:lib/boot/io.smallrye.common.smallrye-common-cpu-2.1.2.jar:lib/boot/io.smallrye.common.smallrye-common-expression-2.1.2.jar:lib/boot/io.smallrye.common.smallrye-common-function-2.1.2.jar:lib/boot/io.smallrye.common.smallrye-common-net-2.1.2.jar:lib/boot/io.smallrye.common.smallrye-common-ref-2.1.2.jar
[0.022s][info][class,path] checking shared classpath entry: /usr/lib/jvm/java-21-openjdk-21.0.1.0.12-3.el8.x86_64/lib/modules
[0.022s][info][class,path] ok
[0.022s][info][class,path] checking shared classpath entry: quarkus-run.jar
[0.022s][info][class,path] ok
[0.022s][info][class,path] checking shared classpath entry: lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar
[0.022s][warning][cds       ] A jar file is not the one used while building the shared archive file: lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar
[0.023s][warning][cds       ] A jar file is not the one used while building the shared archive file: lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar
[0.023s][warning][cds       ] lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar timestamp has changed.
[0.024s][warning][cds,dynamic] Unable to use shared archive. The top archive failed to load: app-cds.jsa

I would suggest changing the layer creation in the quarkus-container-image-jib to ensure that the timestamps are not changed. A common solution for this is to tar the files before moving them to a layer in the image.

Expected behavior

All the libraries that are used when generating the AppCDS archive must be exactly the same as the ones used when creating the image.

Actual behavior

No response

How to Reproduce?

No response

Output of uname -a or ver

Darwin <computer_name> 23.2.0 Darwin Kernel Version 23.2.0: Wed Nov 15 21:53:18 PST 2023; root:xnu-10002.61.3~2/RELEASE_ARM64_T6000 arm64 arm Darwin

Output of java -version

openjdk version "21.0.1" 2023-10-17 OpenJDK Runtime Environment (build 21.0.1+12-29) OpenJDK 64-Bit Server VM (build 21.0.1+12-29, mixed mode, sharing)

Quarkus version or git rev

Quarkus 3.6.3

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.6

Additional information

No response

@davidreis97 davidreis97 added the kind/bug Something isn't working label Jan 5, 2024
Copy link

quarkus-bot bot commented Jan 5, 2024

/cc @geoand (jib)

@geoand
Copy link
Contributor

geoand commented Jan 5, 2024

Thanks for the report!

As you seem to have done an analysis on the source code, would you be interested in providing a fix?

@geoand geoand added the triage/needs-feedback We are waiting for feedback. label Jan 5, 2024
@davidreis97
Copy link
Author

davidreis97 commented Jan 5, 2024

I just compiled the Quarkus main branch and used it to generate the image and could not replicate this issue as the timestamp was properly carried over to the final image. I did this twice. I then went back to Quarkus 3.6.4 and the issue happened again.

So I'd say this has been fixed, although I do not see any new commits in the relevant sections of code - only #37647 which at first glance I'd say is unrelated to this issue I was having, but maybe it is related? In any case, it seems like the next version of Quarkus should fix this for us.

@geoand
Copy link
Contributor

geoand commented Jan 5, 2024

Thanks for checking!

@geoand geoand added triage/out-of-date This issue/PR is no longer valid or relevant and removed triage/needs-feedback We are waiting for feedback. labels Jan 5, 2024
@Pierre-Lemaigre
Copy link

Pierre-Lemaigre commented Feb 1, 2024

Hello, I checked with quarkus version 3.7.1 released yesterday, it is failling with this:

[0.012s][warning][cds] A jar file is not the one used while building the shared archive file: lib/boot/io.quarkus.quarkus-bootstrap-runner-3.7.1.jar
[0.012s][warning][cds] A jar file is not the one used while building the shared archive file: lib/boot/io.quarkus.quarkus-bootstrap-runner-3.7.1.jar
[0.012s][warning][cds] lib/boot/io.quarkus.quarkus-bootstrap-runner-3.7.1.jar timestamp has changed.
[0.013s][warning][cds,dynamic] Unable to use shared archive. The top archive failed to load: app-cds.jsa
__  ____  __  _____   ___  __ ____  ______ 
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
11:18:24 INFO   [co.li.ve.do.wo.OdtTemplateManagerWorker] Startup Event io.quarkus.runtime.StartupEvent@41f4fe5 -> Created template file at path: /home/jboss/template.odt
11:18:24 INFO   [io.quarkus] vectorstodoc 0.0.1-alpha on JVM (powered by Quarkus 3.7.1) started in 0.817s. Listening on: http://0.0.0.0:8080
11:18:24 INFO   [io.quarkus] Profile prod activated. 
11:18:24 INFO   [io.quarkus] Installed features: [cdi, resteasy-reactive, resteasy-reactive-jackson, smallrye-context-propagation, smallrye-openapi, vertx]

I don't know if it is my particular setup that cause the fails, i'm happy to help if you need further infos.

@geoand
Copy link
Contributor

geoand commented Feb 1, 2024

I'll check again soon

@Pierre-Lemaigre
Copy link

Thank you! 👌

@geoand
Copy link
Contributor

geoand commented Feb 1, 2024

I could not reproduce the problem this time either

@davidreis97
Copy link
Author

It's weird, I had the same issue with version 3.6.x, but when I switched to the main branch, the problem disappeared. What's really strange is that I didn't see any code changes between 3.6.x and the main branch that could explain this. Makes me think there might be a sneaky bug hiding somewhere.

@Pierre-Lemaigre
Copy link

Pierre-Lemaigre commented Feb 9, 2024

Re-tested with 3.7.2. It is weird, i have two project, one is fine, the other is not working. The one not working is on java 21, maybe this or the fact that I use a custom image without sha 256 is the root cause. I will investigate more.

@Pierre-Lemaigre
Copy link

Pierre-Lemaigre commented Feb 9, 2024

I think I found the bug. or i'm not sure if it is a bug or the normal behaviour.
Basically if I have anything else than

package com.acme;

import io.quarkus.runtime.Quarkus;
import io.quarkus.runtime.QuarkusApplication;
import io.quarkus.runtime.annotations.QuarkusMain;

@QuarkusMain
public class Main {
    public static void main(String... args) {
        Quarkus.run(MyApp.class, args);
    }

    public static class MyApp implements QuarkusApplication {

        @Override
        public int run(String... args) throws Exception {
            System.out.println("Do startup logic here");
            Quarkus.waitForExit();
            return 0;
        }
    }
}

This mean: Basic autogenerated quarkusmain or defined quarkusmain but without the public static class that extend quarkusapplication, then it does not work.
This is the only difference that make my app working with appcds.
Again i'm not sure if this is the intended behaviour or not, or just a bug because of others dependencies messing with appcds.

@geoand
Copy link
Contributor

geoand commented Feb 9, 2024

Do you mind sharing the application that you came up with that reproduces the problem?

Thanks

@davidreis97
Copy link
Author

Just to note, I also got this error again on 3.7.2, even though just a few weeks ago I was able to make it work with the code on the main branch. Perhaps this issue should be reopened?

Picked up JAVA_TOOL_OPTIONS: -Xlog:cds=debug

[0.022s][info][cds] trying to map /usr/lib/jvm/java-17-openjdk-17.0.10.0.7-2.el8.x86_64/lib/server/classes.jsa
[0.022s][info][cds] Opened archive /usr/lib/jvm/java-17-openjdk-17.0.10.0.7-2.el8.x86_64/lib/server/classes.jsa.
[0.022s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1
[0.022s][info][cds] Core region alignment: 4096
[0.022s][info][cds] trying to map app-cds.jsa
[0.022s][info][cds] Opened archive app-cds.jsa.
[0.022s][info][cds] Archive was created with UseCompressedOops = 1, UseCompressedClassPointers = 1
[0.022s][info][cds] ArchiveRelocationMode == 1: always map archive(s) at an alternative address
[0.022s][info][cds] Try to map archive(s) at an alternative address
[0.022s][info][cds] Reserved archive_space_rs [0x00007fb9d1000000 - 0x00007fb9d4000000] (50331648) bytes
[0.022s][info][cds] Reserved class_space_rs   [0x00007fb9d4000000 - 0x00007fba14000000] (1073741824) bytes
[0.022s][info][cds] Mapped static  region #0 at base 0x00007fb9d1000000 top 0x00007fb9d1455000 (ReadWrite)
[0.022s][info][cds] Mapped static  region #1 at base 0x00007fb9d1455000 top 0x00007fb9d1bc9000 (ReadOnly)
[0.022s][info][cds] Mapped static  region #2 at base 0x00007fba3446b000 top 0x00007fba344a2000 (Bitmap)
[0.060s][info][cds] Mapped dynamic region #0 at base 0x00007fb9d1bc9000 top 0x00007fb9d24ef000 (ReadWrite)
[0.060s][info][cds] Mapped dynamic region #1 at base 0x00007fb9d24ef000 top 0x00007fb9d3230000 (ReadOnly)
[0.060s][info][cds] Mapped dynamic region #2 at base 0x00007fba313fb000 top 0x00007fba31455000 (Bitmap)
[0.069s][info][cds] UseSharedSpaces: A jar file is not the one used while building the shared archive file: lib/boot/org.jboss.logging.jboss-logging-3.5.3.Final.jar
[0.069s][info][cds] Unmapping region #0 at base 0x00007fb9d1bc9000 (ReadWrite)
[0.069s][info][cds] Unmapping region #1 at base 0x00007fb9d24ef000 (ReadOnly)
[0.070s][info][cds] Unmapping region #2 at base 0x00007fba313fb000 (Bitmap)
[0.070s][warning][cds,dynamic] Unable to use shared archive. The top archive failed to load: app-cds.jsa

@geoand
Copy link
Contributor

geoand commented Feb 12, 2024

Perhaps this issue should be reopened?

Sure

@geoand geoand reopened this Feb 12, 2024
@Pierre-Lemaigre
Copy link

Hello,
I was trying to reproduce the bug with different versions. Turns out as of 3.8.2 the bug is no longer here, so for my pov, the issue can be closed. Maybe someone else can comment or follow up on this?

@geoand
Copy link
Contributor

geoand commented Apr 12, 2024

Thanks for checking!

I'll close this and if someone comments it's still an issue, we can reopen

@geoand geoand closed this as completed Apr 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/container-image kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant
Projects
None yet
Development

No branches or pull requests

3 participants