Quarkus 3.12.1 + Kafka + DD + Native = BOOM

[luneo7]

Using Quarku 3.12.1 + Kafka + DD when building native we randomly get errors as:

Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.$get$__datadogContext$(KafkaAdminClient.java) 
Parsing context:
   at datadog.trace.bootstrap.FieldBackedContextStore.get(FieldBackedContextStore.java:17)
   at datadog.trace.bootstrap.instrumentation.java.concurrent.AdviceUtils.capture(AdviceUtils.java:65)
   at java.util.concurrent.ForkJoinTask.fork(ForkJoinTask.java:626)
   at java.math.BigInteger$RecursiveOp.forkOrInvoke(BigInteger.java:1918)
   at java.math.BigInteger$RecursiveOp.square(BigInteger.java:1960)
   at java.math.BigInteger.squareToomCook3(BigInteger.java:2383)
   at java.math.BigInteger.square(BigInteger.java:2227)
   at java.math.BigInteger.multiply(BigInteger.java:1637)
   at java.math.BigInteger.multiply(BigInteger.java:1594)
   at java.math.MutableBigInteger.divide3n2n(MutableBigInteger.java:1370)
   at java.math.MutableBigInteger.divide2n1n(MutableBigInteger.java:1335)
   at java.math.MutableBigInteger.divideAndRemainderBurnikelZiegler(MutableBigInteger.java:1290)
   at java.math.MutableBigInteger.divide(MutableBigInteger.java:1160)
   at java.math.BigInteger.smallToString(BigInteger.java:4164)
   at java.math.BigInteger.toString(BigInteger.java:4217)
   at java.math.BigInteger.toString(BigInteger.java:4112)
   at java.math.BigInteger.toString(BigInteger.java:4286)
   at java.util.Formatter$FormatSpecifier.print(Formatter.java:3451)
   at java.util.Formatter$FormatSpecifier.printInteger(Formatter.java:3064)
   at java.util.Formatter$FormatSpecifier.print(Formatter.java:3021)
   at java.util.Formatter.format(Formatter.java:2780)
   at java.util.Formatter.format(Formatter.java:2728)
   at java.lang.String.format(String.java:4390)
   at jdk.internal.util.Preconditions.outOfBoundsMessage(Preconditions.java:242)
   at jdk.internal.util.Preconditions$4.apply(Preconditions.java:213)
   at jdk.internal.util.Preconditions$4.apply(Preconditions.java:210)
   at jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:98)
   at jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:106)
   at jdk.internal.util.Preconditions.checkIndex(Preconditions.java:302)
   at java.lang.StringUTF16.checkIndex(StringUTF16.java:1613)
   at java.lang.StringUTF16.charAt(StringUTF16.java:1418)
   at java.lang.String.charAt(String.java:1557)
   at java.lang.Long.parseLong(Long.java:689)
   at java.lang.Long.valueOf(Long.java:1157)
   at static root method.(Unknown Source)

        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.AnalysisError.parsingError(AnalysisError.java:149)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.createFlowsGraph(MethodTypeFlow.java:184)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.ensureFlowsGraphCreated(MethodTypeFlow.java:153)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.getOrCreateMethodFlowsGraphInfo(MethodTypeFlow.java:111)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.typestate.DefaultVirtualInvokeTypeFlow.onObservedUpdate(DefaultVirtualInvokeTypeFlow.java:114)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.TypeFlow.update(TypeFlow.java:620)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.PointsToAnalysis$1.run(PointsToAnalysis.java:491)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.CompletionExecutor.executeCommand(CompletionExecutor.java:187)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.CompletionExecutor.lambda$executeService$0(CompletionExecutor.java:171)
        at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1423)
        at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
        at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1312)
        at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1843)
        at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1808)
        at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:188)
Caused by: com.oracle.graal.pointsto.util.AnalysisError: parsing had failed in another thread
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.AnalysisError.shouldNotReachHere(AnalysisError.java:173)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisMethod.ensureGraphParsedHelper(AnalysisMethod.java:871)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisMethod.ensureGraphParsed(AnalysisMethod.java:843)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.parse(MethodTypeFlowBuilder.java:186)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.apply(MethodTypeFlowBuilder.java:621)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.createFlowsGraph(MethodTypeFlow.java:167)
        ... 13 more
Caused by: com.oracle.graal.pointsto.constraints.UnresolvedElementException: Discovered unresolved field during parsing: org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable.__datadogContext$10. This error is reported at image build time because class org.apache.kafka.clients.admin.KafkaAdminClient$AdminClientRunnable is registered for linking at image build time by command line and command line.
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.reportUnresolvedElement(SharedGraphBuilderPhase.java:550)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.reportUnresolvedElement(SharedGraphBuilderPhase.java:544)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.handleUnresolvedField(SharedGraphBuilderPhase.java:453)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.handleUnresolvedLoadField(SharedGraphBuilderPhase.java:363)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.genGetField(BytecodeParser.java:4776)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.genGetField(BytecodeParser.java:4767)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.processBytecode(BytecodeParser.java:5412)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.iterateBytecodesForBlock(BytecodeParser.java:3426)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.iterateBytecodesForBlock(SharedGraphBuilderPhase.java:743)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.handleBytecodeBlock(BytecodeParser.java:3386)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.processBlock(BytecodeParser.java:3228)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.build(BytecodeParser.java:1137)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.build(SharedGraphBuilderPhase.java:162)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.buildRootMethod(BytecodeParser.java:1029)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.GraphBuilderPhase$Instance.run(GraphBuilderPhase.java:101)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase.run(SharedGraphBuilderPhase.java:116)
        at jdk.internal.vm.compiler/org.graalvm.compiler.phases.Phase.run(Phase.java:49)
        at jdk.internal.vm.compiler/org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:434)
        at jdk.internal.vm.compiler/org.graalvm.compiler.phases.Phase.apply(Phase.java:42)
        at jdk.internal.vm.compiler/org.graalvm.compiler.phases.Phase.apply(Phase.java:38)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.AnalysisParsedGraph.parseBytecode(AnalysisParsedGraph.java:146)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisMethod.parseGraph(AnalysisMethod.java:895)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisMethod.ensureGraphParsedHelper(AnalysisMethod.java:860)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisMethod.ensureGraphParsed(AnalysisMethod.java:843)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.phases.InlineBeforeAnalysisGraphDecoder.lookupEncodedGraph(InlineBeforeAnalysisGraphDecoder.java:198)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.doInline(PEGraphDecoder.java:1211)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.tryInline(PEGraphDecoder.java:1194)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.trySimplifyInvoke(PEGraphDecoder.java:1049)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.handleInvokeWithCallTarget(PEGraphDecoder.java:1001)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.handleInvoke(PEGraphDecoder.java:987)
        at jdk.internal.vm.compiler/org.graalvm.compiler.nodes.GraphDecoder.processNextNode(GraphDecoder.java:921)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.phases.InlineBeforeAnalysisGraphDecoder.processNextNode(InlineBeforeAnalysisGraphDecoder.java:378)
        at jdk.internal.vm.compiler/org.graalvm.compiler.nodes.GraphDecoder.decode(GraphDecoder.java:650)
        at jdk.internal.vm.compiler/org.graalvm.compiler.replacements.PEGraphDecoder.decode(PEGraphDecoder.java:892)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.phases.InlineBeforeAnalysis.decodeGraph(InlineBeforeAnalysis.java:76)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.parse(MethodTypeFlowBuilder.java:195)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.apply(MethodTypeFlowBuilder.java:621)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.createFlowsGraph(MethodTypeFlow.java:167)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.ensureFlowsGraphCreated(MethodTypeFlow.java:153)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.MethodTypeFlow.getOrCreateMethodFlowsGraphInfo(MethodTypeFlow.java:111)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.typestate.DefaultVirtualInvokeTypeFlow.onObservedUpdate(DefaultVirtualInvokeTypeFlow.java:114)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.flow.TypeFlow.lambda$addObserver$0(TypeFlow.java:475)
        ... 8 more

The error keeps changing class.. but it is always related to Discovered unresolved field during parsing ... __datadogContext

It seems that the agent transformation might be adding methods before the field? Funny thing is that this doesn't occur with Quarkus 3.8...

I've made a reproducer: https://github.com/luneo7/kafka-with-quarkus
You will need to change the application.properties quarkus.native.container-runtime-options config so the path to dd-java-agent-1.35.2.jar is the correct one...
Later build with mvn clean package -Dquarkus.native.container-build=true -Pnative -DskipTests=true
Sometimes the build passes, so you might need to kick it a few times... funny thing is that in the CI it fails (almost all the time) more than locally...

[mcculls]

Hi @luneo7 - thanks for reporting this, we'll add an update if we find anything

[luneo7]

So, I've tracked that to the bump of kafka libs from 3.6.1 to 3.7.x...
If you do something like:
1 - Change the pom.xml to force kafka 3.6.1

    <properties>
        <kafka3.version>3.6.1</kafka3.version>
    </properties>
...

   <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>org.apache.kafka</groupId>
                <artifactId>kafka-clients</artifactId>
                <version>${kafka3.version}</version>
            </dependency>
            <dependency>
                <groupId>org.apache.kafka</groupId>
                <artifactId>kafka-streams</artifactId>
                <version>${kafka3.version}</version>
            </dependency>
            <dependency>
                <groupId>org.apache.kafka</groupId>
                <artifactId>kafka-streams-test-utils</artifactId>
                <version>${kafka3.version}</version>
            </dependency>
            <dependency>
                <groupId>org.apache.kafka</groupId>
                <artifactId>kafka_2.13</artifactId>
                <version>${kafka3.version}</version>
                <exclusions>
                    <exclusion>
                        <groupId>com.google.code.findbugs</groupId>
                        <artifactId>jsr305</artifactId>
                    </exclusion>
                </exclusions>
            </dependency>
           ...
    </dependencyManagement>

2 - Tell Quarkus to remove the unsafe substitution that isn't needed to be done in the old kafka lib version so the build doesn't fail... change application.properties adding:

quarkus.class-loading.removed-resources."io.quarkus\:quarkus-kafka-client"=io/quarkus/kafka/client/runtime/graal/Target_org_apache_kafka_shaded_com_google_protobuf_UnsafeUtil.class

Then the build will always pass... so the incompatibility lies with kafka libs >= 3.7 ... not Quarkus changes per see...

[luneo7]

@mcculls don't know if it ^ helps... so some change in the Kafka libs broke the DD agent instrumentation during native build... at least it removed Quarkus code changes from the equation :lol:

[vandonr]

@luneo7 what leads you to say that the incompatibility lies with kafka libs >= 3.7 ... not Quarkus changes per se ?
You said earlier that this doesn't occur with Quarkus 3.8, so we cannot say if the issue if coming from Kafka or Quarkus, right ? (most likely it's coming from an interaction between the two)

[luneo7]

@vandonr it is not related to Quarkus, since:
1 - Downgrading the lib, even if it is hacky, it makes the issue go away.
2 - If you check the changes in the Quarkus Kafka extension they are related to the version bump.

[luneo7]

@vandonr it seems that somehow the methods are injected before the variables, or something so the Graal analyzer sees the method but it doesn't see the variable, or that variable naming, which adds somewhat of a counter to it is non deterministic so it is producing wrong var names

[mcculls]

@luneo7 - yes, I believe it's a timing window that Kafka 3.7 happens to increase the probability of it happening.

I'm trying out various options to avoid this timing window.

[luneo7]

@mcculls I've managed to check what is happening... and did a draft for you to take a look: #7402

FieldBackedContextInjector injects methods before all store fields are injected, so GraalVM might see the methods before the fields, a solution for that is to make the method injection happen only in the last injector and not in the first one.

One thing that I noted is that for the keyClassName: org.apache.kafka.clients.consumer.KafkaConsumer , contextClassName: datadog.trace.instrumentation.kafka_clients.KafkaConsumerInfo the visitEnd method is never triggered, so the thread local there for INJECTED_STORE_IDS is not removed (cleaned) and when the thread goes to another class it is being reused so the injected stores doesn't match... it will inject methods for store that won't exist there since it was a store for KafkaConsumer... so the instrumentation for KafkaConsumer might be failing somewhere... didn't dig to see what is failing...

Because of that in that draft I've added a thread local with the current class name, so it can detect when it moved to another class and visitEnd wasn't called, and it will do a reinit to the thread locals...

Does that help with your finding?
That draft makes all our compilation pass, and fixes GraalVM, but doesn't fix what might be happening in the KafkaConsumer instrumentation

[mcculls]

Thanks @luneo7, I've been working on the same area of code. I'll look into that visitEnd issue because it should be called as part of the ASM contract, but maybe something is interrupting the processing.

It's odd about the ordering affecting GraalVM, given that the class-file is only written out after all the transformations have been applied. But maybe it expects class-files to follow a specific ordering/layout - even though that's not required by the usual JVM. I'll try to dig into why this makes a difference to GraalVM.

[luneo7]

Yeah, the main issue might be related to visitEnd not being called, and the thread being used to handle another class and carrying on the thread local store ids and generating methods for stores that doesn't exist. Ideally that class visitor should be atomic in its operations, as it is writing all stores shared by a thread, each instance of it should write code related only to the context store it was created for.

[mcculls]

I tried a smaller patch to avoid the leak caused when visitEnd isn't called and it appears to fix the issue. I'm now digging into why we don't get that call, as it seems to only happen once - specifically just for that Kafka class. But regardless why it's happening I'll still add that check because we'll always want to reset things when processing a new class.

[mcculls]

BTW, the reason why we need to have these injectors collaborate is because there is only one getter/setter per class, which then handles all the different context stores at that level of the class hierarchy. This approach means we can have a single interface vs. having to generate a new interface for every single context store.

[mcculls]

I found the reason why we don't get a call to visitEnd:

java.lang.IllegalStateException: Cannot locate field named metadata for class org.apache.kafka.clients.consumer.KafkaConsumer
        at net.bytebuddy.asm.Advice$OffsetMapping$ForField$Unresolved.resolve(Advice.java:2556)
        at net.bytebuddy.asm.Advice$OffsetMapping$ForField.resolve(Advice.java:2481)
        at net.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$ForMethodExit.doApply(Advice.java:9873)
        at net.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$ForMethodExit.apply(Advice.java:9831)
        at net.bytebuddy.asm.Advice$Dispatcher$Inlining$Resolved$AdviceMethodInliner.visitMethod(Advice.java:9237)
        at net.bytebuddy.jar.asm.ClassReader.readMethod(ClassReader.java:1354)
        at net.bytebuddy.jar.asm.ClassReader.accept(ClassReader.java:745)
        ....

ASM has trouble reading that class and exits early - I imagine this parsing error didn't happen with previous versions of that class, which is why it only shows up recently. I'm going to put in a fix to reset the state of the injector when the class changes (as mentioned earlier these injectors need to work together because only one can create the shared getter/setter per-class)