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

Regression: Quarkus Native Build broken in 7.0.3 #465

Open
lbilger opened this issue Jan 3, 2025 · 10 comments
Open

Regression: Quarkus Native Build broken in 7.0.3 #465

lbilger opened this issue Jan 3, 2025 · 10 comments

Comments

@lbilger
Copy link

lbilger commented Jan 3, 2025

I am using kotlin-logging in a Quarkus application. When upgrading from 7.0.0 to 7.0.3, the native build starts to fail due to logback not being on the class path. The problem was probably introduced with #452. The native build initializes classes eagerly at build time. I tried to fix it with the --intialize-at-run-time option for GraalVM, but could not get it to run.

To reproduce, you can create a simple Quarkus application at https://code.quarkus.io/?e=kotlin and add kotlin-logging as a dependency and add a logger to the GreetingResource class. Then build with ./mvnw clean package -Pnative

The error message from the native build is:

Fatal error: com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing io.github.oshai.kotlinlogging.KotlinLogging.logger(KotlinLogging.kt) 
Parsing context:
   at org.acme.GreetingResource.<init>(GreetingResource.kt:12)
   at org.acme.GreetingResource_Bean.doCreate(Unknown Source)
   at org.acme.GreetingResource_Bean.create(Unknown Source)
   at org.acme.GreetingResource_Bean.create(Unknown Source)
   at io.quarkus.arc.impl.DependentContext.get(DependentContext.java:31)
   at io.quarkus.vertx.http.runtime.HttpCertificateUpdateEventListener_Observer_onCertificateUpdate_38qnWSqwTH2_li9zFUgdvhw5AS4.notify(Unknown Source)
   at io.quarkus.arc.impl.EventImpl$Notifier.notifyObservers(EventImpl.java:351)
   at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:339)
   at io.quarkus.arc.impl.EventImpl$Notifier.notify(EventImpl.java:268)
   at io.quarkus.arc.impl.ArcContainerImpl.shutdown(ArcContainerImpl.java:461)
   at io.quarkus.arc.Arc.shutdown(Arc.java:65)
   at io.quarkus.arc.runtime.ArcRecorder$1.run(ArcRecorder.java:56)
   at io.quarkus.runtime.StartupContext.runAllAndClear(StartupContext.java:79)
   at io.quarkus.runtime.StartupContext.close(StartupContext.java:71)
   at io.quarkus.runner.ApplicationImpl.doStop(Unknown Source)
   at io.quarkus.runtime.Application.stop(Application.java:208)
   at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:219)
   at io.quarkus.runtime.Quarkus.run(Quarkus.java:71)
   at com.oracle.svm.core.JavaMainWrapper.runCore0(JavaMainWrapper.java:237)
   at com.oracle.svm.core.JavaMainWrapper.doRun(JavaMainWrapper.java:293)
   at com.oracle.svm.core.code.IsolateEnterStub.JavaMainWrapper_run_5087f5482cc9a6abc971913ece43acb471d2631b(generated:0)
   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.DefaultSpecialInvokeTypeFlow.lambda$onObservedUpdate$0(DefaultSpecialInvokeTypeFlow.java:88)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.LightImmutableCollection.forEach(LightImmutableCollection.java:90)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.typestate.DefaultSpecialInvokeTypeFlow.onObservedUpdate(DefaultSpecialInvokeTypeFlow.java:87)
        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: org.graalvm.compiler.java.BytecodeParser$BytecodeParserError: org.graalvm.compiler.debug.GraalError: com.oracle.svm.core.util.UserError$UserException: Class initialization of io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory failed. This error is reported at image build time because class io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory is registered for linking at image build time by command line and command line. Use the option 

    '--initialize-at-run-time=io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory'

 to explicitly request initialization of this class at run time.
        at parsing io.github.oshai.kotlinlogging.internal.KLoggerFactory.logger$kotlin_logging(KLoggerFactory.kt:16)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.throwParserError(BytecodeParser.java:2558)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.phases.SharedGraphBuilderPhase$SharedBytecodeParser.throwParserError(SharedGraphBuilderPhase.java:182)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.iterateBytecodesForBlock(BytecodeParser.java:3439)
        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:3391)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.processBlock(BytecodeParser.java:3233)
        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:175)
        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:344)
        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)
        ... 15 more
Caused by: org.graalvm.compiler.debug.GraalError: com.oracle.svm.core.util.UserError$UserException: Class initialization of io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory failed. This error is reported at image build time because class io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory is registered for linking at image build time by command line and command line. Use the option 

    '--initialize-at-run-time=io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory'

 to explicitly request initialization of this class at run time.
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.AnalysisFuture.setException(AnalysisFuture.java:49)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:322)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.AnalysisFuture.ensureDone(AnalysisFuture.java:63)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.ensureOnTypeReachableTaskDone(AnalysisType.java:696)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.onReachable(AnalysisType.java:590)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.util.AtomicUtils.atomicSetAndRun(AtomicUtils.java:49)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.lambda$registerAsReachable$8(AnalysisType.java:562)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.forAllSuperTypes(AnalysisType.java:676)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.forAllSuperTypes(AnalysisType.java:659)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.forAllSuperTypes(AnalysisType.java:655)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.registerAsReachable(AnalysisType.java:562)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisUniverse.lookupAllowUnresolved(AnalysisUniverse.java:368)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.infrastructure.AnalysisConstantPool.lookupField(AnalysisConstantPool.java:42)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.lookupField(BytecodeParser.java:4364)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.genGetStatic(BytecodeParser.java:4924)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.processBytecode(BytecodeParser.java:5435)
        at jdk.internal.vm.compiler/org.graalvm.compiler.java.BytecodeParser.iterateBytecodesForBlock(BytecodeParser.java:3431)
        ... 45 more
Caused by: com.oracle.svm.core.util.UserError$UserException: Class initialization of io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory failed. This error is reported at image build time because class io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory is registered for linking at image build time by command line and command line. Use the option 

    '--initialize-at-run-time=io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory'

 to explicitly request initialization of this class at run time.
        at org.graalvm.nativeimage.builder/com.oracle.svm.core.util.UserError.abort(UserError.java:85)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ClassInitializationSupport.ensureClassInitialized(ClassInitializationSupport.java:187)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.AllowAllHostedUsagesClassInitializationSupport.computeInitKindAndMaybeInitializeClass(AllowAllHostedUsagesClassInitializationSupport.java:191)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.AllowAllHostedUsagesClassInitializationSupport.computeInitKindAndMaybeInitializeClass(AllowAllHostedUsagesClassInitializationSupport.java:129)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ClassInitializationSupport.maybeInitializeAtBuildTime(ClassInitializationSupport.java:161)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ClassInitializationSupport.maybeInitializeAtBuildTime(ClassInitializationSupport.java:150)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.SVMHost.onTypeReachable(SVMHost.java:310)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisUniverse.onTypeReachable(AnalysisUniverse.java:699)
        at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.meta.AnalysisType.lambda$new$0(AnalysisType.java:310)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
        ... 60 more
Caused by: java.lang.NoClassDefFoundError: ch/qos/logback/classic/spi/LogbackServiceProvider
        at io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory.createLogbackServiceProvider(LogbackLoggerFactory.kt:13)
        at io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory.<clinit>(LogbackLoggerFactory.kt:10)
        at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method)
        at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1160)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ClassInitializationSupport.ensureClassInitialized(ClassInitializationSupport.java:177)
        ... 69 more
Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.LogbackServiceProvider
        at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:641)
        at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:188)
        at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:526)
        at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageClassLoader.loadClass(NativeImageClassLoader.java:652)
        at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:526)
        ... 74 more
Copy link

github-actions bot commented Jan 3, 2025

Thank you for reporting an issue. See the wiki for documentation and slack for questions.

@oshai
Copy link
Owner

oshai commented Jan 3, 2025

Hi, is this different in any way than slf4j which we also have as a compile only dependency?

@oshai
Copy link
Owner

oshai commented Jan 3, 2025

Does adding logback to the classpath solves the issue?

@lbilger
Copy link
Author

lbilger commented Jan 3, 2025

Hi @oshai, thanks for the quick reply!

  • I guess it is different only in so far as slf4j is on the classpath of a Quarkus app by default. Removing slf4j from the classpath would probably have a similar effect, but I can't easily test that because it's a dependency of Quarkus.
  • adding logback-classic to the classpath fixes the native build. But I'm not sure if this will break anything else because there are two logging implementations on the classpath then.

@oshai
Copy link
Owner

oshai commented Jan 3, 2025

I am not graal expert but it seems that preventing from class loading other classes like this is the way to fix this:
--initialize-at-run-time=io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory

You mentioned it didn’t work though. I wonder if any other code change might have similar effect, Maybe instead of import, loading the class via reflection for example.

@lbilger
Copy link
Author

lbilger commented Jan 3, 2025

I don't know much about the Graal internals either, but I'm guessing that the initialize-at-run-time is ineffective because the class is transitively used by an application class that is initialized at build-time. So it can't avoid initializing it at build-time also.

What surprises me is that the LogbackLoggerFactory shouldn't even be called if the kotlin-logging-to-logback system property is not set. Maybe Graal is being smart there and thinking "the property might be set at run-time, so I need to initialize that class as well". Or maybe it is related to LogbackLoggerFactory being an object, not a simple class.

Loading the class via reflection would probably help. It would mean that if you want to use it in a native build, you'd have to @RegisterForReflection it. But that seems acceptable to me.

May I ask what is the advantage of the explicit logback support anyway? I always thought that logback supports slf4j out of the box, so why this extra wrapper instead of just using it through slf4j?

@oshai
Copy link
Owner

oshai commented Jan 5, 2025

May I ask what is the advantage of the explicit logback support anyway?

There are slight differences in the api between slf4j and logback, you can see #449 for more details.

Another suggestion:

Can you try configure a reachability handler to avoid loading those classes:

ch.qos.logback.classic.Logger
ch.qos.logback.classic.LoggerContext
ch.qos.logback.classic.spi.LogbackServiceProvider

Something like this:

public class MyFeature implements Feature {
    @Override
    public void beforeAnalysis(BeforeAnalysisAccess access) {
        access.registerReachabilityHandler((context, reason) -> {
            // Skip loading or initializing
        }, ch.qos.logback.classic.Logger.class);
    }
}

@lbilger
Copy link
Author

lbilger commented Jan 6, 2025

I think this would not work - to add such a handler, I would need to have Logback on the classpath (because I need a Class object for the Logback classes I want to exclude).

I wanted to try this approach for the LogbackLoggerFactory but that also doesn't work because it is internal and can't be accessed from my app.

I also build a version of kotlin-logging locally where Class.forName("io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory") is used instead of referencing the object directly, but that still didn't help. Probably, as mentioned in the page you linked, Graal is also processing this because the class name is a constant.

It works with Class.forName(" io.github.oshai.kotlinlogging.logback.internal.LogbackLoggerFactory ".trim()) but that is such an ugly workaround that I don't want to suggest it.

@oshai
Copy link
Owner

oshai commented Jan 6, 2025

I am not sure that for reachability handler you must have the class in classpath, definitely not in the image classpath. See an example from gemini: https://g.co/gemini/share/ab1a595a81a0

@lbilger
Copy link
Author

lbilger commented Jan 7, 2025

I cannot find anything about that class com.oracle.svm.core.jdk.ReachabilityHandler. There is com.oracle.svm.hosted.ReachabilityHandler, but that has a different API. Might Gemini be hallucinating here?
All the APIs I can find to influence the reachability analysis require a Class object as a parameter...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants