ObjectMapperCustomizer only evaluated at build time if resteasy-reactive-jackson or rest-client-reactive-jackson present

manofthepeace commented 1 year ago

Describe the bug

I would like to customize my object mapper depending on a configproperty. When I use the quarkus-jackson dependency it all works well, but if I use or quarkus-resteasy-reactive-jackson or quarkus-rest-client-reactive-jackson , it then make it evaluated only at build time using native, and it does not execute while running the app anymore.

The only workaround I found is to have a basic singleton @Startup bean that re-customizes the Objectmapper.

Expected behavior

ObjectMapperCustomizer should run at runtime event it it ran at buildtime so it can work with configproperty/configmapping.

via logs it should look like this at compile time; [2/7] Performing analysis... [***]

and running the app;

MY_VARIABLE=prod ./target/jackson-customize-issue-1.0.0-SNAPSHOT-runner
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2023-04-27 15:55:48,906 INFO  [org.acm.RegisterCustomModuleCustomizer] (main) Customizing objectMapper for prod

Actual behavior

ObjectMapper gets customized at buildtime only;

grallvm build;

[2/7] Performing analysis... [15:44:59,592 INFO [org.acm.RegisterCustomModuleCustomizer] Customizing objectMapper for default

app log; nothing gets logged from the customizer

How to Reproduce?

Reproduce: https://github.com/manofthepeace/quarkus-jackson-buildtime-issue

Steps to reproduce

mvn clean package -Pnative
./target/jackson-customize-issue-1.0.0-SNAPSHOT-runner (should print default at runtime)
MY_VARIABLE=prod ./target/jackson-customize-issue-1.0.0-SNAPSHOT-runner (should print prod at runtime)
Modify the pom.xml, remove the quarkus-jackson dependency and uncomment one or both of the resteasy-reactive ones
recompile via mvn clean package -Pnative
observes the log at build time during the graalvm processing phase
rerun step 2 and 3, will not print, and default is always actually used

Output of `uname -a` or `ver`

Darwin Kernel Version 21.6.0

Output of `java -version`

OpenJDK Runtime Environment Temurin-17.0.7+7 (build 17.0.7+7)

GraalVM version (if different from Java)

21.3.1

Quarkus version or git rev

2.16.6

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

Apache Maven 3.8.7

Additional information

No response

quarkus-bot[bot] commented 1 year ago

/cc @FroMage (resteasy-reactive), @Sgitario (rest-client,resteasy-reactive), @cescoffier (rest-client), @geoand (jackson,rest-client,resteasy-reactive), @gsmet (jackson), @stuartwdouglas (resteasy-reactive)

geoand commented 1 year ago

Does this problem only happen in native mode?

manofthepeace commented 1 year ago

Yes this only happens in native mode. In Jvm mode I do not see the log at built time, only at runtime, with the right value

geoand commented 1 year ago

Understood, thanks

geoand commented 1 year ago

https://github.com/quarkusio/quarkus/pull/33189 takes care of it

manofthepeace commented 1 year ago

@geoand I dont understand how yet, but this is not fixed in my application. I have tried on the reproducer, and the fix indeed works, but in my main app I still see the class being initialized at build time and not at runtime. I have added the following --trace-object-instantiation=org.acme.MyClass in the native build param, but whatever class I put there I do not see any extra log printing while building. Would you have any idea how I could determine the culprit?

I have also tried to add al pom dependencies from may app to the reproducer, and enhance a little the reproducer but the reproducer still works fine, the main app doesn't.

geoand commented 1 year ago

Would you have any idea how I could determine the culprit?

Not off hand unfortunately

manofthepeace commented 1 year ago

@geoand sorry for the ping again. Does that help? Still unsure how to have a reproducer for it but was able to get that stacktrace;

Error: Classes that should be initialized at run time got initialized during image building:
 org.acme.ObjectMapperConfigurator the class was requested to be initialized at run time (from command line with 'org.acme.ObjectMapperConfigurator'). io.quarkus.runner.ApplicationImpl caused initialization of this class with the following trace:
    at org.acme.ObjectMapperConfigurator.<clinit>(ObjectMapperConfigurator.java:14)
    at org.acme.ObjectMapperConfigurator_Bean.doCreate(Unknown Source)
    at org.acme.ObjectMapperConfigurator_Bean.create(Unknown Source)
    at org.acme.ObjectMapperConfigurator_Bean.create(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
    at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
    at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
    at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
    at org.acme.ObjectMapperConfigurator_Bean.get(Unknown Source)
    at org.acme.ObjectMapperConfigurator_Bean.get(Unknown Source)
    at io.quarkus.arc.impl.Instances.getBeanInstance(Instances.java:115)
    at io.quarkus.arc.impl.Instances.listOf(Instances.java:75)
    at io.quarkus.arc.impl.ListProvider.get(ListProvider.java:50)
    at io.quarkus.arc.impl.ListProvider.get(ListProvider.java:15)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.doCreate(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.create(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.create(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
    at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
    at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
    at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.get(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.get(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.FullyFeaturedServerJacksonMessageBodyWriter_Bean.doCreate(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.FullyFeaturedServerJacksonMessageBodyWriter_Bean.create(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.FullyFeaturedServerJacksonMessageBodyWriter_Bean.get(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.FullyFeaturedServerJacksonMessageBodyWriter_Bean.get(Unknown Source)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:499)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:479)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:512)
    at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:287)
    at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:284)
    at io.quarkus.arc.runtime.BeanContainerImpl$1.create(BeanContainerImpl.java:46)
    at io.quarkus.resteasy.reactive.common.runtime.ArcBeanFactory.createInstance(ArcBeanFactory.java:27)
    at org.jboss.resteasy.reactive.common.model.ResourceWriter.instance(ResourceWriter.java:80)
    at org.jboss.resteasy.reactive.common.core.Serialisers.toMessageBodyWriters(Serialisers.java:203)
    at org.jboss.resteasy.reactive.common.core.Serialisers.findBuildTimeWriters(Serialisers.java:157)
    at org.jboss.resteasy.reactive.server.core.startup.RuntimeResourceDeployment.buildResourceMethod(RuntimeResourceDeployment.java:422)
    at org.jboss.resteasy.reactive.server.core.startup.RuntimeDeploymentManager.deploy(RuntimeDeploymentManager.java:122)
    at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder.createDeployment(ResteasyReactiveRecorder.java:184)
    at io.quarkus.deployment.steps.ResteasyReactiveProcessor$setupDeployment1637929001.deploy_3(Unknown Source)
    at io.quarkus.deployment.steps.ResteasyReactiveProcessor$setupDeployment1637929001.deploy(Unknown Source)
    at io.quarkus.runner.ApplicationImpl.<clinit>(Unknown Source)

manofthepeace commented 1 year ago

I have updated the previous reproducer here; https://github.com/manofthepeace/quarkus-jackson-buildtime-issue

To reproduce you can follow steps in OP.

Thank you

geoand commented 1 year ago

I'll have a look in a few days

geoand commented 1 year ago

I am not sure what I am supposed to be looking at to see the updated problem in action.

manofthepeace commented 1 year ago

Sorry for the lack of information. Problem is only for native but lets compare;

If you run this way (not native) java -jar target/quarkus-app/quarkus-run.jar you will see a log Customizing objectMapper for default and this MY_VARIABLE=prod java -jar target/quarkus-app/quarkus-run.jar will show this; Customizing objectMapper for prod

in native while building this log is shown [2/7] Performing analysis... [09:28:55,774 INFO [org.acm.RegisterCustomModuleCustomizer] Customizing objectMapper for default at runtime this is not re-initialized so running the all like this ./target/jackson-customize-issue-1.0.0-SNAPSHOT-runner or MY_VARIABLE=prod ./target/jackson-customize-issue-1.0.0-SNAPSHOT-runner, wont show the log, and use the default config.

when using mvn clean package -DskipTests -Pnative -Dquarkus.native.additional-build-args="--initialize-at-run-time=org.acme.RegisterCustomModuleCustomizer,--trace-class-initialization=org.acme.RegisterCustomModuleCustomizer"

The following exception is thrown (please note the exception I had pasted above (with my main app) is using FullyFeaturedServerJacksonMessageBodyWriter and the reproducer this one BasicServerJacksonMessageBodyWriter) but the outcome seems similar

com.oracle.svm.core.util.UserError$UserException: Classes that should be initialized at run time got initialized during image building:
 org.acme.RegisterCustomModuleCustomizer the class was requested to be initialized at run time (from command line with 'org.acme.RegisterCustomModuleCustomizer'). io.quarkus.runner.ApplicationImpl caused initialization of this class with the following trace:
    at org.acme.RegisterCustomModuleCustomizer.<clinit>(RegisterCustomModuleCustomizer.java)
    at org.acme.RegisterCustomModuleCustomizer_Bean.doCreate(Unknown Source)
    at org.acme.RegisterCustomModuleCustomizer_Bean.create(Unknown Source)
    at org.acme.RegisterCustomModuleCustomizer_Bean.create(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
    at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
    at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
    at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
    at org.acme.RegisterCustomModuleCustomizer_Bean.get(Unknown Source)
    at org.acme.RegisterCustomModuleCustomizer_Bean.get(Unknown Source)
    at io.quarkus.arc.impl.Instances.getBeanInstance(Instances.java:115)
    at io.quarkus.arc.impl.Instances.listOf(Instances.java:75)
    at io.quarkus.arc.impl.ListProvider.get(ListProvider.java:50)
    at io.quarkus.arc.impl.ListProvider.get(ListProvider.java:15)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.doCreate(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.create(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.create(Unknown Source)
    at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
    at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
    at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
    at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
    at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.get(Unknown Source)
    at io.quarkus.jackson.runtime.ObjectMapperProducer_ProducerMethod_objectMapper_d2925203309586fa5cde23a83b2025591c2d3832_Bean.get(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.BasicServerJacksonMessageBodyWriter_Bean.doCreate(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.BasicServerJacksonMessageBodyWriter_Bean.create(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.BasicServerJacksonMessageBodyWriter_Bean.get(Unknown Source)
    at io.quarkus.resteasy.reactive.jackson.runtime.serialisers.BasicServerJacksonMessageBodyWriter_Bean.get(Unknown Source)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:499)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:479)
    at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:512)
    at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:287)
    at io.quarkus.arc.impl.ArcContainerImpl$2.get(ArcContainerImpl.java:284)
    at io.quarkus.arc.runtime.BeanContainerImpl$1.create(BeanContainerImpl.java:46)
    at io.quarkus.resteasy.reactive.common.runtime.ArcBeanFactory.createInstance(ArcBeanFactory.java:27)
    at org.jboss.resteasy.reactive.common.model.ResourceWriter.instance(ResourceWriter.java:80)
    at org.jboss.resteasy.reactive.common.core.Serialisers.toMessageBodyWriters(Serialisers.java:203)
    at org.jboss.resteasy.reactive.common.core.Serialisers.findBuildTimeWriters(Serialisers.java:157)
    at org.jboss.resteasy.reactive.server.core.startup.RuntimeResourceDeployment.buildResourceMethod(RuntimeResourceDeployment.java:422)
    at org.jboss.resteasy.reactive.server.core.startup.RuntimeDeploymentManager.deploy(RuntimeDeploymentManager.java:122)
    at io.quarkus.resteasy.reactive.server.runtime.ResteasyReactiveRecorder.createDeployment(ResteasyReactiveRecorder.java:184)
    at io.quarkus.deployment.steps.ResteasyReactiveProcessor$setupDeployment1637929001.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.ResteasyReactiveProcessor$setupDeployment1637929001.deploy(Unknown Source)
    at io.quarkus.runner.ApplicationImpl.<clinit>(Unknown Source)

Please let me know if anything and thank you for your time.

geoand commented 1 year ago

Gotcha, thanks

geoand commented 1 year ago

This seems to be caused by the presence of the prometheus metrics extension, but I still haven't dug deep enough to know what we can do about it.

manofthepeace commented 1 year ago

I tried removing the extension from the reproducer and the same happens. I was more under the impression it was in resteasy somewhere since it started to happen in the reproducer once I did an api that took or returned a jackson entity, returning or taking a String for example did not cause the issue as I recall.

manofthepeace commented 1 year ago

can this be reopened?

quarkusio / quarkus