Compilation fails when using new Logging with Panache and logging in try/catch

[tanadeau]

Describe the bug

After upgrading to Quarkus 2.3.0.Final, I wanted to use the new Logging with Panache functionality. After removing all explicit static loggers and replacing with the Quarkus Log, I ended up with the compilation failure as seen below. If I didn't log within catch clauses, compilation succeeded as expected.

Expected behavior

Compilation succeeds.

Actual behavior

Compilation fails during class transformation build step:

> Task :backend:quarkusBuild
building quarkus jar

> Task :backend:quarkusBuild FAILED

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':backend:quarkusBuild'.
> io.quarkus.builder.BuildException: Build failure: Build failed due to errors
        [error]: Build step io.quarkus.deployment.steps.ClassTransformingBuildStep#handleClassTransformation threw an exception: java.lang.IllegalStateException: java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: LocalVariablesSorter only accepts expanded frames (see ClassReader.EXPAND_FRAMES)
        at io.quarkus.deployment.ExtensionLoader$2.execute(ExtensionLoader.java:829)
        at io.quarkus.builder.BuildContext.run(BuildContext.java:277)
        at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at java.base/java.lang.Thread.run(Thread.java:829)
        at org.jboss.threads.JBossThread.run(JBossThread.java:501)
  Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalArgumentException: LocalVariablesSorter only accepts expanded frames (see ClassReader.EXPAND_FRAMES)
        at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at io.quarkus.deployment.steps.ClassTransformingBuildStep.handleClassTransformation(ClassTransformingBuildStep.java:229)
        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.deployment.ExtensionLoader$2.execute(ExtensionLoader.java:820)
        ... 6 more
  Caused by: java.lang.IllegalArgumentException: LocalVariablesSorter only accepts expanded frames (see ClassReader.EXPAND_FRAMES)
        at org.objectweb.asm.commons.LocalVariablesSorter.visitFrame(LocalVariablesSorter.java:189)
        at org.objectweb.asm.MethodVisitor.visitFrame(MethodVisitor.java:300)
        at org.objectweb.asm.ClassReader.readCode(ClassReader.java:2052)
        at org.objectweb.asm.ClassReader.readMethod(ClassReader.java:1491)
        at org.objectweb.asm.ClassReader.accept(ClassReader.java:721)
        at org.objectweb.asm.ClassReader.accept(ClassReader.java:401)
        at io.quarkus.deployment.steps.ClassTransformingBuildStep.transformClass(ClassTransformingBuildStep.java:315)
        at io.quarkus.deployment.steps.ClassTransformingBuildStep$2.call(ClassTransformingBuildStep.java:202)
        at io.quarkus.deployment.steps.ClassTransformingBuildStep$2.call(ClassTransformingBuildStep.java:189)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)

How to Reproduce?

No response

Output of uname -a or ver

Darwin C02YK01PLVCG-ML 20.6.0 Darwin Kernel Version 20.6.0: Mon Aug 30 06:12:21 PDT 2021; root:xnu-7195.141.6~3/RELEASE_X86_64 x86_64

Output of java -version

openjdk version "11.0.11" 2021-04-20 OpenJDK Runtime Environment AdoptOpenJDK-11.0.11+9 (build 11.0.11+9) OpenJDK 64-Bit Server VM AdoptOpenJDK-11.0.11+9 (build 11.0.11+9, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.3.0.Final

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

------------------------------------------------------------ Gradle 7.2 ------------------------------------------------------------ Build time: 2021-08-17 09:59:03 UTC Revision: a773786b58bb28710e3dc96c4d1a7063628952ad Kotlin: 1.5.21 Groovy: 3.0.8 Ant: Apache Ant(TM) version 1.10.9 compiled on September 27 2020 JVM: 11.0.11 (AdoptOpenJDK 11.0.11+9) OS: Mac OS X 11.5 x86_64

Additional information

No response

[quarkus-bot]

/cc @FroMage, @evanchooly, @loicmathieu

[geoand]

cc @Ladicek

[Ladicek]

I added a simple test with logging in a catch clause and that works fine. Based on the exception, it seems similar to another bug report from Zulip (https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Panache.20Log). If you could provide a source code of a class that contains an offending Log.* statement, that would be nice! (In the meantime, I'll try to reproduce with RESTEasy Reactive, based on the Zulip chat description.)

[Ladicek]

Nope, I couldn't reproduce this based on the (limited) information from Zulip. I'm afraid I'm gonna need a reproducer.

[tanadeau]

I’ll see if I can create one this week. Just as an FYI, I was using normal RESTEasy.

[dwamara]

Been having the same problem, no try-catch for me, just plain logging. Didn't knew it had to do with the Log with Panache, so commented it out and the compilation passed.

[Ladicek]

Thanks to the people on Zulip, I have a reproducer:

1. add a dependency on quarkus-hibernate-orm-panache
2. add a method like this to some class:

public void hello() {
    if (Math.random() > 0L) {}
    Log.info("Hello!");
}

Note that if I remove the if, compilation will succeed.

[dwamara]

Thanks to the people on Zulip, I have a reproducer:

1. add a dependency on quarkus-hibernate-orm-panache

2. add a method like this to some class:

public void hello() {

    if (Math.random() > 0L) {}

    Log.info("Hello!");

}

Note that if I remove the if, compilation will succeed.

Could it be that is has to do with the presence of the hibernate with panache dependency in the pom.xml because I had it as a dependency too.

[Ladicek]

Indeed that is the case. There are 2 class transformers generated for the same class, and the Hibernate with Panache transformation accidentally comes later than the Logging with Panache one. Which results in class reader options begin reset, and then the Logging with Panache transformation fails.

[Ladicek]

Fix is in #20664.