infov impacts local variable type

[legrosmanu]

Describe the bug

I propose here a very specific problem, but, unfortunately, during a POC of a team to see if Quarkus could replace Spring Boot, the trust of the team on Quarkus is impacted.

Log.infov with more than 1 variable related to a Kafka record, seems to change the type of a local variable in specific context.

The specific context is:

• the first line is a Uni not initialized explicitly (no = null for example), but the result would be the same with a CompletionStage.
• a Log.infov is used with 2 variables related to a Kafka record

It means:

@Incoming("prices")
    public Uni<Void> consume(ConsumerRecord<String, String> msg) {
        Uni<Void> result; // result = null will work, or even if Instant now = Instant.now(); if before this line
        Instant now = Instant.now();

        Log.infov("infov seems changing now into a long, {0} - {1}", msg.topic(), msg.offset());
        // Log.infov("infov seems changing now into a long, {0}", msg.topic()); will work

        methodThatGetAnInstant(now);

        result = Uni.createFrom().voidItem();
        return result;
    }

    private void methodThatGetAnInstant(Instant instant) {
        Log.info("What a wonderfull method.");
    }

Expected behavior

We would expect mvn quarkus:dev starts the service without errors.

Actual behavior

We have an error on mvn quarkus:dev

2023-04-15 11:16:11,240 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (Aesh InputStream Reader) Failed to start quarkus: io.quarkus.dev.appstate.ApplicationStartException: java.lang.RuntimeException: Failed to start quarkus
	at io.quarkus.dev.appstate.ApplicationStateNotification.waitForApplicationStart(ApplicationStateNotification.java:58)
	at io.quarkus.runner.bootstrap.StartupActionImpl.runMainClass(StartupActionImpl.java:123)
	at io.quarkus.deployment.dev.IsolatedDevModeMain.restartApp(IsolatedDevModeMain.java:222)
	at io.quarkus.deployment.dev.IsolatedDevModeMain.restartCallback(IsolatedDevModeMain.java:203)
	at io.quarkus.deployment.dev.RuntimeUpdatesProcessor.doScan(RuntimeUpdatesProcessor.java:543)
	at io.quarkus.deployment.console.ConsoleStateManager.forceRestart(ConsoleStateManager.java:141)
	at io.quarkus.deployment.console.ConsoleStateManager.lambda$installBuiltins$0(ConsoleStateManager.java:98)
	at io.quarkus.deployment.console.ConsoleStateManager$1.accept(ConsoleStateManager.java:73)
	at io.quarkus.deployment.console.ConsoleStateManager$1.accept(ConsoleStateManager.java:46)
	at io.quarkus.deployment.console.AeshConsole.lambda$setup$1(AeshConsole.java:275)
	at org.aesh.terminal.EventDecoder.accept(EventDecoder.java:118)
	at org.aesh.terminal.EventDecoder.accept(EventDecoder.java:31)
	at org.aesh.terminal.io.Decoder.write(Decoder.java:133)
	at org.aesh.readline.tty.terminal.TerminalConnection.openBlocking(TerminalConnection.java:216)
	at org.aesh.readline.tty.terminal.TerminalConnection.openBlocking(TerminalConnection.java:203)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
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 io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:111)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:71)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:44)
	at io.quarkus.runtime.Quarkus.run(Quarkus.java:124)
	at io.quarkus.runner.GeneratedMain.main(Unknown Source)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:104)
	... 1 more
Caused by: jakarta.enterprise.inject.spi.DefinitionException: java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    legros/emmanuel/KafkaConsumer.consume(Lorg/apache/kafka/clients/consumer/ConsumerRecord;)Lio/smallrye/mutiny/Uni; @52: invokevirtual
  Reason:
    Type 'java/lang/Long' (current frame, stack[1]) is not assignable to 'java/time/Instant'
  Current Frame:
    bci: @52
    flags: { }
    locals: { 'legros/emmanuel/KafkaConsumer', 'org/apache/kafka/clients/consumer/ConsumerRecord', 'java/lang/Long', top, top, 'java/lang/String', top, 'java/lang/String' }
    stack: { 'legros/emmanuel/KafkaConsumer', 'java/lang/Long' }
  Bytecode:
    0000000: b800 074d 120d 2bb6 000f b800 15b2 005f
    0000010: 5b57 b600 6212 212b b600 232b b600 0fb8
    0000020: 0015 4d3a 053a 07b2 005f 1907 1905 2cb6
    0000030: 0063 2a2c b600 2ab8 0030 b600 363a 0819
    0000040: 08b0                                   

	at io.smallrye.reactive.messaging.providers.extension.MediatorManager.createMediator(MediatorManager.java:199)
	at io.smallrye.reactive.messaging.providers.extension.MediatorManager_ClientProxy.createMediator(Unknown Source)
	at io.smallrye.reactive.messaging.providers.wiring.Wiring$SubscriberMediatorComponent.materialize(Wiring.java:626)
	at io.smallrye.reactive.messaging.providers.wiring.Graph.lambda$materialize$10(Graph.java:100)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
	at io.smallrye.reactive.messaging.providers.wiring.Graph.materialize(Graph.java:99)
	at io.smallrye.reactive.messaging.providers.extension.MediatorManager.start(MediatorManager.java:219)
	at io.smallrye.reactive.messaging.providers.extension.MediatorManager_ClientProxy.start(Unknown Source)
	at io.quarkus.smallrye.reactivemessaging.runtime.SmallRyeReactiveMessagingLifecycle.onApplicationStart(SmallRyeReactiveMessagingLifecycle.java:52)
	at io.quarkus.smallrye.reactivemessaging.runtime.SmallRyeReactiveMessagingLifecycle_Observer_onApplicationStart_68e7b57eb97cb75d597c5b816682366e888d0d9b.notify(Unknown Source)
	at io.quarkus.arc.impl.EventImpl$Notifier.notifyObservers(EventImpl.java:344)
	at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:326)
	at io.quarkus.arc.impl.EventImpl.fire(EventImpl.java:82)
	at io.quarkus.arc.runtime.ArcRecorder.fireLifecycleEvent(ArcRecorder.java:151)
	at io.quarkus.arc.runtime.ArcRecorder.handleLifecycleEvents(ArcRecorder.java:102)
	at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy_0(Unknown Source)
	at io.quarkus.deployment.steps.LifecycleEventsBuildStep$startupEvent1144526294.deploy(Unknown Source)
	... 13 more
Caused by: java.lang.VerifyError: Bad type on operand stack
Exception Details:
  Location:
    legros/emmanuel/KafkaConsumer.consume(Lorg/apache/kafka/clients/consumer/ConsumerRecord;)Lio/smallrye/mutiny/Uni; @52: invokevirtual
  Reason:
    Type 'java/lang/Long' (current frame, stack[1]) is not assignable to 'java/time/Instant'
  Current Frame:
    bci: @52
    flags: { }
    locals: { 'legros/emmanuel/KafkaConsumer', 'org/apache/kafka/clients/consumer/ConsumerRecord', 'java/lang/Long', top, top, 'java/lang/String', top, 'java/lang/String' }
    stack: { 'legros/emmanuel/KafkaConsumer', 'java/lang/Long' }
  Bytecode:
    0000000: b800 074d 120d 2bb6 000f b800 15b2 005f
    0000010: 5b57 b600 6212 212b b600 232b b600 0fb8
    0000020: 0015 4d3a 053a 07b2 005f 1907 1905 2cb6
    0000030: 0063 2a2c b600 2ab8 0030 b600 363a 0819
    0000040: 08b0                                   

	at legros.emmanuel.KafkaConsumer_Bean.proxy(Unknown Source)
	at legros.emmanuel.KafkaConsumer_Bean.get(Unknown Source)
	at legros.emmanuel.KafkaConsumer_Bean.get(Unknown Source)
	at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:477)
	at io.quarkus.arc.impl.ArcContainerImpl.beanInstanceHandle(ArcContainerImpl.java:490)
	at io.quarkus.arc.impl.BeanManagerImpl.getReference(BeanManagerImpl.java:63)
	at io.smallrye.reactive.messaging.providers.extension.MediatorManager.createMediator(MediatorManager.java:176)
	... 29 more

How to Reproduce?

I think that the description of the bug already explains how to reproduce it, but to make it simple, I propose you more comments on the following code -> https://github.com/legrosmanu/quarkus-infov-issue/blob/main/src/main/java/legros/emmanuel/KafkaConsumer.java

On this project, you can do a mvn:quarkus to get the error.

You'll have the same issue with Quarkus 2.6 or 3.0

Output of uname -a or ver

Darwin **** 22.4.0 Darwin Kernel Version 22.4.0: Mon Mar 6 21:00:17 PST 2023; root:xnu-8796.101.5~3/RELEASE_X86_64 x86_64

Output of java -version

OpenJDK Runtime Environment Temurin-17.0.6+10 (build 17.0.6+10) OpenJDK 64-Bit Server VM Temurin-17.0.6+10 (build 17.0.6+10, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.0.0.CR2

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

Apache Maven 3.9.1 (2e178502fcdbffc201671fb2537d0cb4b4cc58f8) Maven home: /usr/local/Cellar/maven/3.9.1/libexec Java version: 17.0.6, vendor: Eclipse Adoptium, runtime: /Users/manu/.sdkman/candidates/java/17.0.6-tem Default locale: fr_FR, platform encoding: UTF-8 OS name: "mac os x", version: "13.3", arch: "x86_64", family: "mac"

Additional information

No response

[gsmet]

@Ladicek could it be your Log magic doing weird things?

@legrosmanu could you try using a standard logger instead?

Create a field like so:

private static final Logger LOG = Logger.getLogger(YourClass.class);

with Logger being org.jboss.logging.Logger and use it to log instead of Log.

[legrosmanu]

Hi @gsmet,
Thanks for the proposal, but I proposed this bug to be fixed if it is interesting for the community.
Indeed, It is very easy to not have the issue even with keeping this logger. The minimal workaround is to write Uni result = null; instead of Uni result;

[gsmet]

I totally agree we need to fix it. My question was more to try to narrow down the issue.

[Ladicek]

Yeah, this totally looks like the bytecode transformation not preserving the stack state properly. I'll take a look.

[quarkus-bot]

/cc @FroMage (panache), @Sgitario (rest-data-panache), @loicmathieu (panache)

[Ladicek]

The problem is that I'm using the LocalVariablesSorter API incorrectly (as eloquently described in https://stackoverflow.com/questions/50140365/asm-strange-localvar-index-using-newlocal-from-localvariablesorter), so the resulting bytecode doesn't obey the JVM stack discipline. I'll submit a PR in a bit.

[Ladicek]

#32679 should fix this.