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

Bug in Quarkus bytecode generation #31153

Closed
rdehuyss opened this issue Feb 14, 2023 · 14 comments · Fixed by #31183
Closed

Bug in Quarkus bytecode generation #31153

rdehuyss opened this issue Feb 14, 2023 · 14 comments · Fixed by #31183
Labels
area/core kind/bug Something isn't working
Milestone

Comments

@rdehuyss
Copy link
Contributor

rdehuyss commented Feb 14, 2023

Describe the bug

Hi all, I'm Ronald, the creator of JobRunr, a Quartz replacement.

JobRunr also integrates with Quarkus and to do so, I created a custom Quarkus Extension. I'm currently struggling with this extension.

In this extension, I've written a RecurringJobsFinder that searches for all methods annotated with @Recurring and schedules them using a recorder so that the bytecode is recorded.

This is all tested by means of integration tests here:
https://github.com/jobrunr/jobrunr/blob/bugfix/689/framework-support/jobrunr-quarkus-extension/tests/src/main/java/org/jobrunr/quarkus/it/TestService.java#L20-L25

All of this mostly works fine but for one of these recurring jobs, I receive the following exception:

java.lang.RuntimeException: Failed to start quarkus
java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.test.junit.QuarkusTestExtension.throwBootFailureException(QuarkusTestExtension.java:625)
    at io.quarkus.test.junit.QuarkusTestExtension.interceptTestClassConstructor(QuarkusTestExtension.java:696)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
       ...
Caused by: java.lang.RuntimeException: Failed to start quarkus
    at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
    at io.quarkus.runtime.Application.start(Application.java:101)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at io.quarkus.runner.bootstrap.StartupActionImpl.run(StartupActionImpl.java:253)
    at io.quarkus.test.junit.QuarkusTestExtension.doJavaStart(QuarkusTestExtension.java:250)
    at io.quarkus.test.junit.QuarkusTestExtension.ensureStarted(QuarkusTestExtension.java:592)
    at io.quarkus.test.junit.QuarkusTestExtension.beforeAll(QuarkusTestExtension.java:640)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$12(ClassBasedTestDescriptor.java:395)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:395)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:211)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:84)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:148)
    ... 52 more
Caused by: java.lang.UnsupportedOperationException
    at java.base/java.util.Collections$UnmodifiableCollection.add(Collections.java:1060)
    at io.quarkus.deployment.steps.JobRunrExtensionProcessor$findRecurringJobAnnotationsAndScheduleThem1351984528.deploy_0(Unknown Source)
    at io.quarkus.deployment.steps.JobRunrExtensionProcessor$findRecurringJobAnnotationsAndScheduleThem1351984528.deploy(Unknown Source)
    ... 68 more

The bytecode generated by the Recorder is as follows (thanks @gastaldi!):

    public void deploy_0(StartupContext var1, Object[] var2) {
        JobRunrRecurringJobRecorder var4 = new JobRunrRecurringJobRecorder();
        ArrayList var3 = new ArrayList();
        JobDetails var6 = new JobDetails("org.jobrunr.quarkus.it.TestService", (String)null, "aRecurringJob", (List)var3);
        Object var5 = var1.getValue("proxykey93");
        var4.schedule((BeanContainer)var5, "my-recurring-job", var6, "*/15 * * * *", (String)null, (String)null);
        ArrayList var7 = new ArrayList(1);
        JobParameter var8 = new JobParameter("org.jobrunr.jobs.context.JobContext", "org.jobrunr.jobs.context.JobContext", (Object)null);
        ((Collection)var7).add(var8);
        JobDetails var10 = new JobDetails("org.jobrunr.quarkus.it.TestService", (String)null, "anotherRecurringJob", (List)var7);
        ((Collection)var10.getJobParameters()).add(var8);
        Object var9 = var1.getValue("proxykey93");
        var4.schedule((BeanContainer)var9, "another-recurring-job-with-jobContext", var10, (String)null, "PT10M", (String)null);
    }

We noticed that var8 is added twice for some reason. As ((Collection)var10.getJobParameters()) returns an unmodifiable list, the second add fails. But, I do not understand the reason why the parameter is added twice in the first place as that will also cause problems later on in JobRunr (2 parameters where the method only expects 1).

Expected behavior

The parameter should only be added once.

Actual behavior

The parameter is added twice.

How to Reproduce?

  1. git clone https://github.com/jobrunr/jobrunr
  2. git checkout bugfix/689
  3. import project in Intellij
  4. Run test ./framework-support/jobrunr-quarkus-extension/tests/src/test/java/org/jobrunr/quarkus/it/JobRunrFunctionalityTest.java

Output of uname -a or ver

Darwin Ronalds-MacBook-Pro.local 21.6.0 Darwin Kernel Version 21.6.0: Thu Sep 29 20:13:56 PDT 2022; root:xnu-8020.240.7~1/RELEASE_ARM64_T6000 arm64

Output of java -version

openjdk version "17.0.1" 2021-10-19 OpenJDK Runtime Environment (build 17.0.1+12-39) OpenJDK 64-Bit Server VM (build 17.0.1+12-39, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.15.3

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

Gradle 7.5.1

Additional information

See also the analysis of @gastaldi at https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/JobRunr.20Quarkus.20extension.20-.20UnsupportedOperationException

@rdehuyss rdehuyss added the kind/bug Something isn't working label Feb 14, 2023
@quarkus-bot
Copy link

quarkus-bot bot commented Feb 14, 2023

You added a link to a Zulip discussion, please make sure the description of the issue is comprehensive and doesn't require accessing Zulip

This message is automatically generated by a bot.

@quarkus-bot
Copy link

quarkus-bot bot commented Feb 14, 2023

/cc @Sanne (core), @aloubyansky (core), @geoand (core), @gsmet (core), @radcortez (core), @stuartwdouglas (core)

@geoand
Copy link
Contributor

geoand commented Feb 14, 2023

@gastaldi are you looking into this?

@gastaldi
Copy link
Contributor

@geoand I am, but I am having a hard time trying to reproduce it in a test case. Wanna take a look?

@geoand
Copy link
Contributor

geoand commented Feb 14, 2023

I can have a look tomorrow

@gastaldi
Copy link
Contributor

I've narrowed down to this snippet which adds the offending line. Still investigating

Collection propertyValue = (Collection) i.read(param);
if (propertyValue != null && !propertyValue.isEmpty()) {
List<DeferredParameter> params = new ArrayList<>();
for (Object c : propertyValue) {
DeferredParameter toAdd = loadObjectInstance(c, existing, Object.class, relaxedValidation);
params.add(toAdd);
}
setupSteps.add(new SerializationStep() {
@Override
public void handle(MethodContext context, MethodCreator method,
DeferredArrayStoreParameter out) {
//get the collection
ResultHandle prop = method.invokeVirtualMethod(
MethodDescriptor.ofMethod(i.getReadMethod()),
context.loadDeferred(out));
for (DeferredParameter i : params) {
//add the parameter
//TODO: this is not guarded against large collections, probably not an issue in practice
method.invokeInterfaceMethod(COLLECTION_ADD, prop, context.loadDeferred(i));
}
}
@Override
public void prepare(MethodContext context) {
for (DeferredParameter i : params) {
i.prepare(context);
}
}
});
}

@gastaldi
Copy link
Contributor

gastaldi commented Feb 14, 2023

@rdehuyss the problem is that the BytecodeGenerator is failing to construct the JobDetails object when the recorder is called. Not saying this isn't exactly a bug, but if you want to fix you may want to try the following:

  • Change the org.jobrunr.scheduling.JobRunrRecurringJobRecorder#schedule method signature and constructing the JobDetails object there seems to fix the problem:
    public void schedule(BeanContainer container, String id, String cron, String interval, String zoneId, String className, String methodName, List<JobParameter> parameterList) {
        JobScheduler scheduler = container.instance(JobScheduler.class);
        String jobId = getId(id);
        String optionalCronExpression = getCronExpression(cron);
        String optionalInterval = getInterval(interval);

        if (StringUtils.isNullOrEmpty(cron) && StringUtils.isNullOrEmpty(optionalInterval))
            throw new IllegalArgumentException("Either cron or interval attribute is required.");
        if (StringUtils.isNotNullOrEmpty(cron) && StringUtils.isNotNullOrEmpty(optionalInterval))
            throw new IllegalArgumentException("Both cron and interval attribute provided. Only one is allowed.");

        if (Recurring.RECURRING_JOB_DISABLED.equals(optionalCronExpression) || Recurring.RECURRING_JOB_DISABLED.equals(optionalInterval)) {
            if (isNullOrEmpty(jobId)) {
                LOGGER.warn("You are trying to disable a recurring job using placeholders but did not define an id.");
            } else {
                scheduler.delete(jobId);
            }
        } else {
            JobDetails jobDetails = new JobDetails(className, null, methodName, parameterList);
            jobDetails.setCacheable(true);
            if (isNotNullOrEmpty(optionalCronExpression)) {
                scheduler.scheduleRecurrently(id, jobDetails, CronExpression.create(optionalCronExpression), getZoneId(zoneId));
            } else {
                scheduler.scheduleRecurrently(id, jobDetails, new Interval(optionalInterval), getZoneId(zoneId));
            }
        }
    }

gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 14, 2023
@gastaldi
Copy link
Contributor

gastaldi commented Feb 14, 2023

I managed to reproduce this in a test case: gastaldi@dab48a0

In case you're interested @geoand ☝🏻

gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 14, 2023
@rdehuyss
Copy link
Contributor Author

I just wanted to say - wauw! Thank you all and especially @gastaldi for taking this so serious and providing a workaround so fast!

rdehuyss added a commit to jobrunr/jobrunr that referenced this issue Feb 14, 2023
@geoand
Copy link
Contributor

geoand commented Feb 15, 2023

@gastaldi excellent investigation!

Looking at your test, I immediately see that the object is not really deserialiable in bytecode, because:

  • The default constructor is private
  • there is no @RecordableConstructor annotation on one of the other constructors.

If the @RecordableConstructor annotation cannot be added to a class, then the options are:

  • Use the io.quarkus.deployment.recording.RecorderContext#registerSubstitution(Class, Class, Class) mechanism
  • Use the io.quarkus.deployment.recording.RecordingAnnotationsProvider SPI along with some arbitrary annotation which will allow Quarkus to pick a constructor.

More information can be found here.

@geoand
Copy link
Contributor

geoand commented Feb 15, 2023

@rdehuyss when you have time, can you try one of the above proposals and see if the the issue goes away?

@rdehuyss
Copy link
Contributor Author

@geoand
Copy link
Contributor

geoand commented Feb 15, 2023

Oh sorry, I had not seen that.

Ladicek pushed a commit to Ladicek/quarkus that referenced this issue Feb 15, 2023
Ladicek added a commit to Ladicek/quarkus that referenced this issue Feb 15, 2023
Ladicek added a commit to Ladicek/quarkus that referenced this issue Feb 15, 2023
@Ladicek
Copy link
Contributor

Ladicek commented Feb 15, 2023

I took a [not so] quick look and eventually found what I believe is the crux of the issue.

The bytecode recording mechanism attempts to match constructor parameters to properties and skip setting properties that were initialized by the constructor. The assumption is that if the constructor has a parameter with the same name as the property, the property is set by the constructor. Otherwise it needs to be set using a setter.

The issue is that this matching was not implemented for the "explicitly registered non-default constructor" mechanism, which is used here. That's pretty easy to fix: https://github.com/Ladicek/quarkus/commits/bytecode_recorder_collection

gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 15, 2023
gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 15, 2023
gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 15, 2023
@quarkus-bot quarkus-bot bot added this to the 3.0 - main milestone Feb 16, 2023
gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 16, 2023
gastaldi added a commit to gastaldi/quarkus that referenced this issue Feb 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/core kind/bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants