Hacking/efficient restbucks

[anthonydahanne]

No description provided.

[anthonydahanne]

replaces #121

[anthonydahanne]

CI is running in: https://github.com/anthonydahanne/spring-restbucks/actions

[anthonydahanne]

Hello @odrotbohm and @sdeleuze 👋 !
So I got back to your repo Oliver, since I owed you a working arm64 buildpack PR since April 🙂
And I saw you changed a bit your pom, with SB3, just the regular SB packaging, etc.
Anyway, I've added 2 build profiles: 1 to produce a regular OCI image, (with CDS and AOT of course, it's 2024!) and another to create a native app OCI image.
well, guess what, none of them work 😩

• Regular OCI image: CDS fails because of bytebuddy? or maybe because it tries to connect to something?
• Native app OCI image: graalvm native build fails because of org.springframework.boot.loader.nio.file.NestedFileSystemProvider and bytebuddy?

Did I miss something obvious?
Please let me know! thanks!

[sdeleuze]

For CDS + AOT, the ByteBuddy warnings are expected because it is built with a Java 6 baseline and this is not compatible with CDS, it is not expected to be blocking, I have created raphw/byte-buddy#1657 related issue.

The error is more likely due to the error message [INFO] [creator] Parameter 1 of constructor in org.springsource.restbucks.payment.PaymentServiceImpl required a bean of type 'org.springsource.restbucks.payment.Payments' that could not be found. you can see in the logs. Maybe @odrotbohm will know how to fix it, but for a start I would suggest to only enable CDS without AOT since the latter is not side effect free.

Also make sure to configure the application to avoid early DB interaction in the training run as documented here.

Native build seems broken by the NestedFileSystemProvider error.

[anthonydahanne]

Thanks @sdeleuze for your input!

---

So I could make the CDS build work, disabling AOT.
I compared Restbucks OCI image startup time on my machine without CDS

18:50:45.986 I -     main : Started Restbucks in 3.685 seconds (process running for 4.045)

with CDS

18:49:28.359 I -     main : Started Restbucks in 1.953 seconds (process running for 2.467)

so it looks fine; you can try it out, I've published it for 24h via CI:

docker run -it -p 8080:8080 ttl.sh/restbucks-e713c48c092efd8090250a7bc03d37c0b3e302b7:1d

It's built on x86, so on your mac don't expect a fast startup😅

---

Now, for native, I'm not sure what you meant with:

Native build seems broken by the NestedFileSystemProvider error.

You can see the error there, during the step 2/8 of the GraalVM build.

As far as I know, it's pulled by ByteBuddy

Actually, I googled some more, and... the excellent @wilkinsona already helped someone on SO, and, quite ironically, linked to an issue in... paketo-buildpacks/native-image#321 😂

But unfortunately, now the native image dies at runtime because of some missing logging conf. classes?!

Logging system failed to initialize using configuration from 'null'
java.lang.IllegalStateException: Logback configuration error detected: 
ERROR in ch.qos.logback.core.pattern.parser.Compiler@92c3255 - Failed to instantiate converter class [ch.qos.logback.classic.pattern.DateConverter] for keyword [d] ch.qos.logback.core.util.DynamicClassLoadingException: Failed to instantiate type ch.qos.logback.classic.pattern.DateConverter

I published it too, check it out:

docker run -it -p 8080:8080 ttl.sh/restbucks-native-e713c48c092efd8090250a7bc03d37c0b3e302b7:1d

[sdeleuze]

The related exception above seems about ch.qos.logback.classic.pattern.DateConverter which is included in the reachability metadata.

I see a src/main/resources/logback.xml file is provided, which is handled by Spring Boot if I am not mistaken. To be confirmed with @wilkinsona and @odrotbohm but I suspect the pattern configured is maybe using a feature not supported by Spring Boot. If that's correct, maybe you can workaround by removing src/main/resources/logback.xml and there is maybe a related Boot issue to create.

@anthonydahanne Could you please check if the application is working as expected when removing that file and doing a clean build?

[wilkinsona]

%d should work. To verify, I just updated the logging-logback-xml smoke test to use Restbucks' logback.xml. The native image ran as expected and produced log output like this:

> Task :boot:logging-logback-xml:nativeRun

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::       (v3.3.1-SNAPSHOT)

08:33:51.446 I -     main : Starting AOT-processed LogbackXmlApplication using Java 17.0.10 with PID 65554 (/Users/awilkinson/dev/spring-projects/spring-aot-smoke-tests/main/boot/logging-logback-xml/build/native/nativeCompile/logging-logback-xml started by awilkinson in /Users/awilkinson/dev/spring-projects/spring-aot-smoke-tests/main/boot/logging-logback-xml)
08:33:51.446 I -     main : No active profile set, falling back to 1 default profile: "default"
08:33:51.453 I -     main : Started LogbackXmlApplication in 0.023 seconds (process running for 0.038)
08:33:51.453 I -     main : Info message
08:33:51.453 W -     main : Warn message
08:33:51.453 E -     main : Error message
08:33:51.453 I -     main : Info with parameters: 1

[anthonydahanne]

well, the mystery deepens for me...
I removed src/main/resources/logback.xml , cleared target, rebuilt with ./mvnw -Pbuildpacks-native and if the image successfully got produced, at runtime I got:

docker run -it restbucks:1.0.0-SNAPSHOT
  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::                (v3.3.0)

%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]%PARSER_ERROR[d] %PARSER_ERROR[p] 1 --- [restbucks] [%PARSER_ERROR[t]] %PARSER_ERROR[logger] : %PARSER_ERROR[m]%PARSER_ERROR[n]Application run failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'entityManagerFactory': null
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1784)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:601)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:523)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:336)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:296)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:334)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:204)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:960)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:625)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:146)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:456)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:335)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1363)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1352)
	at org.springsource.restbucks.Restbucks.main(Restbucks.java:57)
	at [email protected]/java.lang.invoke.LambdaForm$DMH/sa346b79c.invokeStaticInit(LambdaForm$DMH)
Caused by: java.lang.ExceptionInInitializerError
	at org.springframework.orm.jpa.vendor.SpringHibernateJpaPersistenceProvider.createContainerEntityManagerFactory(SpringHibernateJpaPersistenceProvider.java:54)
	at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:390)
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.buildNativeEntityManagerFactory(AbstractEntityManagerFactoryBean.java:419)
	at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:400)
	at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.afterPropertiesSet(LocalContainerEntityManagerFactoryBean.java:366)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1831)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1780)
	... 16 more
Caused by: java.lang.IllegalArgumentException: Invalid logger interface org.hibernate.internal.EntityManagerMessageLogger (implementation not found in jdk.internal.loader.ClassLoaders$AppClassLoader@27f674d)
	at org.jboss.logging.Logger.doGetMessageLogger(Logger.java:2573)
	at org.jboss.logging.Logger.getMessageLogger(Logger.java:2532)
	at org.jboss.logging.Logger.getMessageLogger(Logger.java:2518)
	at org.hibernate.internal.HEMLogging.messageLogger(HEMLogging.java:28)
	at org.hibernate.internal.HEMLogging.messageLogger(HEMLogging.java:24)
	at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.<clinit>(EntityManagerFactoryBuilderImpl.java:142)
	... 23 more

[wilkinsona]

Both the %PARSER_ERRORs and the invalid logger interface suggest that the reachability metadata hasn't been used when building the image. As @sdeleuze noted above, the problem with DateConverter could also be a symptom of the reachability metadata not being used.

[sdeleuze]

Same analysis than @wilkinsona, and when building the native application with ./mvnw -Pnative, I am back on the Parameter 1 of constructor in org.springsource.restbucks.payment.PaymentServiceImpl required a bean of type 'org.springsource.restbucks.payment.Payments' that could not be found. error which likley happens after the logback one.

@anthonydahanne Maybe when building with ./mvnw -Pbuildpacks-native you don't enable the native Maven profile so you miss the plugin org.graalvm.buildtools:native-maven-plugin which brings the reachability metadata?

@odrotbohm Could you please help us to understand why AOT and native builds seems broken with this PaymentServiceImpl error (I get that error when following the README instructions with no Buildpacks involved)?

[odrotbohm]

It looks like the error also appears on main for ./mvnw -Pnative. Investigating.

[odrotbohm]

If I remove the upgrade to Spring Framework 6.2 from the pom.xml the native binary runs successfully. I'll discuss this with the core Spring Framework team.

[odrotbohm]

It looks like we're dealing with a regression in the AOT handling of Framework 6.2. I've created a branch hacking/framework-regression to revert the upgrade to 6.2 for you to be able to proceed by rebasing your current efforts on that branch.

[odrotbohm]

Thanks, everyone, for your involvement. On plain Boot 3.3, I get @anthonydahanne's changes working once I add the metadata repository inclusiong to the buildpacks-native profile. I was also able to remove a few of the workarounds for the previously unfixed glitches in Boot and buildpacks.

I'll go ahead and rearrange master to stay on Framework 6.1 for now and move the 6.2 related changes to a dedicated branch. The AOT bug we ran into was fixed, but there's apparently been additional, more invasive changes to the AOT infrastructure that currently render 6.2 snapshots incompatible with Boot 3.3 and 3.4 snapshots.

Long story short: I'll take it from here. Thanks! 🙇

[odrotbohm]

The contribution is now available in main.