search

vitaliihonta / zio-temporal

Build invincible apps with ZIO and https://temporal.io
https://zio-temporal.vhonta.dev
Apache License 2.0
67 stars 10 forks source link

Research GraalVM native image compatability #91

Open vitaliihonta opened 1 year ago

vitaliihonta commented 1 year ago

Take a look at @carlosedp example here https://github.com/carlosedp/zio-temporal-hello/tree/main/shared/resources/META-INF/native-image

I believe it could be handled somehow

carlosedp commented 1 year ago

While the native-image.properties initialization flags had to be added by hand, most json config files could be generated dynamically by using GraalVM native-image tracing agent.

The biggest quirk is that when I generate this metadata by using an e2e test, a mock temporal server is used so the agent apparently doesn't hit the GRPC classes not including them in the metadata so the generated binary fails.

When the metadata is generated with a real run of the worker and a real workflow execution, the binary works (supposedly all classes are found).

Some refs:

Binary error when running with the e2e generated metadata:

❯ /Users/cdepaula/repos/scala/zio-temporal-hello/out/worker/nativeImage.dest/ziotemporalworker
timestamp=2023-07-04T16:48:15.521712-03:00 level=INFO thread=zio-fiber-6 message="HTTP Metrics Server started at http://localhost:8082/metrics" source=<empty>.Main.run
timestamp=2023-07-04T16:48:15.522017-03:00 level=INFO thread=zio-fiber-6 message="Started sample-worker listening to queue echo-queue" source=<empty>.Worker
timestamp=2023-07-04T16:48:15.538768-03:00 level=INFO thread=zio-fiber-6 message="ZWorkerFactory started" source=zio.temporal.worker.ZWorkerFactory
timestamp=2023-07-04T16:48:19.862526-03:00 level=DEBUG thread=zio-fiber-303 message="Received from null, message: CLI Msg" source=<empty>.EchoActivityImpl
timestamp=2023-07-04T16:48:19.862697-03:00 level=DEBUG thread=zio-fiber-303 message="Worker: Generated percent is 45" source=<empty>.EchoActivityImpl
timestamp=2023-07-04T16:48:19.862785-03:00 level=ERROR thread=zio-fiber-303 message="Worker: eventuallyFail - Failed to process message" source=<empty>.EchoActivityImpl
timestamp=2023-07-04T16:48:19.86304-03:00  level=DEBUG thread=zio-fiber-303 message="Fiber zio-fiber-303 did not handle an error" cause=Exception in thread "zio-fiber-303" scala.util.Right: Right(java.lang.Exception: Worker: ERROR: ACK: CLI Msg)
    at zio.temporal.internal.ZioUnsafeFacade.unsafeRunAsyncZIO.errorsHandled(ZioUnsafeFacade.scala:18)
    at zio.temporal.internal.ZioUnsafeFacade.unsafeRunAsyncZIO.fiber(ZioUnsafeFacade.scala:20) source=zio.temporal.internal.ZioUnsafeFacade.unsafeRunAsyncZIO
timestamp=2023-07-04T16:48:19.86381-03:00  level=WARN thread=zio-fiber-311 message="Activity failure. ActivityId=04a32ab1-ec26-35d2-86de-dbb0e83ec6c8, activityType=Echo, attempt=1" cause=Exception in thread "zio-fiber-" io.temporal.client.ActivityCompletionFailureException: null
    at io.temporal.internal.client.external.ManualActivityCompletionClientImpl.fail(ManualActivityCompletionClientImpl.java:171)
    at io.temporal.client.ActivityCompletionClientImpl.completeExceptionally(ActivityCompletionClientImpl.java:73)
    at java.base@17.0.7/java.lang.reflect.Method.invoke(Method.java:568)
    at io.temporal.internal.WorkflowThreadMarker.lambda$protectFromWorkflowThread$1(WorkflowThreadMarker.java:83)
    at jdk.proxy4/jdk.proxy4.$Proxy48.completeExceptionally(Unknown Source)
    at zio.temporal.activity.ZActivity$.runAsyncImpl$$anonfun$2(ZActivity.scala:113)
    at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    at zio.temporal.internal.ZioUnsafeFacade$.unsafeRunAsyncZIO$$anonfun$1$$anonfun$1(ZioUnsafeFacade.scala:25)
    at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
    at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
    Suppressed: java.lang.RuntimeException: Generated message class "io.temporal.api.workflowservice.v1.RespondActivityTaskFailedRequest" missing method "getTaskToken".
        at com.google.protobuf.GeneratedMessageV3.getMethodOrDie(GeneratedMessageV3.java:1929)
        at com.google.protobuf.GeneratedMessageV3.access$1000(GeneratedMessageV3.java:79)
        at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable$SingularFieldAccessor$ReflectionInvoker.<init>(GeneratedMessageV3.java:2260)
        at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable$SingularFieldAccessor.<init>(GeneratedMessageV3.java:2334)
        at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable.ensureFieldAccessorsInitialized(GeneratedMessageV3.java:2064)
        at io.temporal.api.workflowservice.v1.RespondActivityTaskFailedRequest.internalGetFieldAccessorTable(RespondActivityTaskFailedRequest.java:126)
        at com.google.protobuf.GeneratedMessageV3.getDescriptorForType(GeneratedMessageV3.java:133)
        at com.google.protobuf.TextFormat$Printer.print(TextFormat.java:364)
        at com.google.protobuf.TextFormat$Printer.print(TextFormat.java:354)
        at com.google.protobuf.TextFormat$Printer.printToString(TextFormat.java:619)
        at com.google.protobuf.AbstractMessage.toString(AbstractMessage.java:111)
        at java.base@17.0.7/java.lang.String.valueOf(String.java:4216)
        at java.base@17.0.7/java.lang.StringBuilder.append(StringBuilder.java:173)
        at io.temporal.serviceclient.GrpcTracingInterceptor$1.sendMessage(GrpcTracingInterceptor.java:53)
        at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37)
        at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37)
        at io.grpc.stub.ClientCalls.asyncUnaryRequestCall(ClientCalls.java:317)
        at io.grpc.stub.ClientCalls.futureUnaryCall(ClientCalls.java:227)
        at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:154)
        at io.temporal.api.workflowservice.v1.WorkflowServiceGrpc$WorkflowServiceBlockingStub.respondActivityTaskFailed(WorkflowServiceGrpc.java:3868)
        at io.temporal.internal.client.external.ManualActivityCompletionClientImpl.lambda$fail$2(ManualActivityCompletionClientImpl.java:163)
        at io.temporal.internal.retryer.GrpcRetryer.lambda$retry$0(GrpcRetryer.java:52)
        at io.temporal.internal.retryer.GrpcSyncRetryer.retry(GrpcSyncRetryer.java:69)
        at io.temporal.internal.retryer.GrpcRetryer.retryWithResult(GrpcRetryer.java:60)
        at io.temporal.internal.retryer.GrpcRetryer.retry(GrpcRetryer.java:50)
        at io.temporal.internal.client.external.ManualActivityCompletionClientImpl.fail(ManualActivityCompletionClientImpl.java:158)
        at io.temporal.client.ActivityCompletionClientImpl.completeExceptionally(ActivityCompletionClientImpl.java:73)
        at java.base@17.0.7/java.lang.reflect.Method.invoke(Method.java:568)
        at io.temporal.internal.WorkflowThreadMarker.lambda$protectFromWorkflowThread$1(WorkflowThreadMarker.java:83)
        at jdk.proxy4/jdk.proxy4.$Proxy48.completeExceptionally(Unknown Source)
        at zio.temporal.activity.ZActivity$.runAsyncImpl$$anonfun$2(ZActivity.scala:113)
        at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
        at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
        at zio.temporal.internal.ZioUnsafeFacade$.unsafeRunAsyncZIO$$anonfun$1$$anonfun$1(ZioUnsafeFacade.scala:25)
        at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
        at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
        Suppressed: java.lang.NoSuchMethodException: io.temporal.api.workflowservice.v1.RespondActivityTaskFailedRequest.getTaskToken()
            at java.base@17.0.7/java.lang.Class.getMethod(DynamicHub.java:2227)
            at com.google.protobuf.GeneratedMessageV3.getMethodOrDie(GeneratedMessageV3.java:1926)
            at com.google.protobuf.GeneratedMessageV3.access$1000(GeneratedMessageV3.java:79)
            at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable$SingularFieldAccessor$ReflectionInvoker.<init>(GeneratedMessageV3.java:2260)
            at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable$SingularFieldAccessor.<init>(GeneratedMessageV3.java:2334)
            at com.google.protobuf.GeneratedMessageV3$FieldAccessorTable.ensureFieldAccessorsInitialized(GeneratedMessageV3.java:2064)
            at io.temporal.api.workflowservice.v1.RespondActivityTaskFailedRequest.internalGetFieldAccessorTable(RespondActivityTaskFailedRequest.java:126)
            at com.google.protobuf.GeneratedMessageV3.getDescriptorForType(GeneratedMessageV3.java:133)
            at com.google.protobuf.TextFormat$Printer.print(TextFormat.java:364)
            at com.google.protobuf.TextFormat$Printer.print(TextFormat.java:354)
            at com.google.protobuf.TextFormat$Printer.printToString(TextFormat.java:619)
            at com.google.protobuf.AbstractMessage.toString(AbstractMessage.java:111)
            at java.base@17.0.7/java.lang.String.valueOf(String.java:4216)
            at java.base@17.0.7/java.lang.StringBuilder.append(StringBuilder.java:173)
            at io.temporal.serviceclient.GrpcTracingInterceptor$1.sendMessage(GrpcTracingInterceptor.java:53)
            at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37)
            at io.grpc.ForwardingClientCall.sendMessage(ForwardingClientCall.java:37)
            at io.grpc.stub.ClientCalls.asyncUnaryRequestCall(ClientCalls.java:317)
            at io.grpc.stub.ClientCalls.futureUnaryCall(ClientCalls.java:227)
            at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:154)
            at io.temporal.api.workflowservice.v1.WorkflowServiceGrpc$WorkflowServiceBlockingStub.respondActivityTaskFailed(WorkflowServiceGrpc.java:3868)
            at io.temporal.internal.client.external.ManualActivityCompletionClientImpl.lambda$fail$2(ManualActivityCompletionClientImpl.java:163)
            at io.temporal.internal.retryer.GrpcRetryer.lambda$retry$0(GrpcRetryer.java:52)
            at io.temporal.internal.retryer.GrpcSyncRetryer.retry(GrpcSyncRetryer.java:69)
            at io.temporal.internal.retryer.GrpcRetryer.retryWithResult(GrpcRetryer.java:60)
            at io.temporal.internal.retryer.GrpcRetryer.retry(GrpcRetryer.java:50)
            at io.temporal.internal.client.external.ManualActivityCompletionClientImpl.fail(ManualActivityCompletionClientImpl.java:158)
            at io.temporal.client.ActivityCompletionClientImpl.completeExceptionally(ActivityCompletionClientImpl.java:73)
            at java.base@17.0.7/java.lang.reflect.Method.invoke(Method.java:568)
            at io.temporal.internal.WorkflowThreadMarker.lambda$protectFromWorkflowThread$1(WorkflowThreadMarker.java:83)
            at jdk.proxy4/jdk.proxy4.$Proxy48.completeExceptionally(Unknown Source)
            at zio.temporal.activity.ZActivity$.runAsyncImpl$$anonfun$2(ZActivity.scala:113)
            at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
            at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10)
            at zio.temporal.internal.ZioUnsafeFacade$.unsafeRunAsyncZIO$$anonfun$1$$anonfun$1(ZioUnsafeFacade.scala:25)
            at scala.runtime.function.JProcedure1.apply(JProcedure1.java:15)
            at scala.runtime.function.JProcedure1.apply(JProcedure1.java:10) source=io.temporal.internal.activity.ActivityTaskExecutors$ActivityTaskExecutor
carlosedp commented 1 year ago

There are two points on this IMO, one is the proxy/reflection/jni metadata, the other is initialization flags.

Reflection/proxy/etc metadata could be handled by the tracing agent as I described above.

For the initialization, most flags from the native-image.properties had to be added after I enabled the zio-logging-slf4j2-bridge... if you look into this commit, all the flags that were added were required after adding the log lib. The native-image binary worked with the existing ones previous to this commit if not using the log lib.

My big gripe is where all this initialization flags should be?

@Spikhalskiy, would you take a look at this since you worked on GraalVM in Temporal SDK?

carlosedp commented 1 year ago

On talks with GraalVM guys (https://twitter.com/carlosedp/status/1675945560119865350), I found that all classes are initialized at run-time by default so looking at GraalVM PRs, I found https://github.com/oracle/graal/pull/3179/files that added a flag to exclude configs from regexes.

Since a lot of libs bundle initialization rules, I've added to my native-image build the flag regex'ing out all .properties from all jars to bypass the initialize flags from them and also removed all flags added to the project locally.

In the end I've successfully built the native-image tackling one of the issues listed above. The other one is how to properly generate the json metadata automatically.

Since zio-temporal also uses reflection, I don't think bundling this into the library solves since the user's workflows and activities should also be added as it can be seen in https://github.com/carlosedp/zio-temporal-hello/blob/3f33c09d6cf2cec201eec5b3bf8d3e33fc172481/shared/resources/META-INF/native-image/proxy-config.json#L18-L21.

Here's the PR removing the flags and excluding lib configs: https://github.com/carlosedp/zio-temporal-hello/pull/4

carlosedp commented 1 year ago

One thought I had is that we could bundle the reflection/proxy/etc json metadata for the zio-temporal and temporal classes (like the GRPC ones) in zio-temporal and kinda automate the generation of the additional metadata required by the user application (like the activities and workflows) at build time.

In talks with Alex Archambault, he mentioned they do that in scala-cli... I searched and it's here: https://github.com/VirtusLab/scala-cli/blob/a7b887a45fadc158cafa37a14dcbac8dd0ea36ca/project/settings.sc#L414-L435

At native-image generation, it creates the metadata beforehand. Some docs are here: https://github.com/VirtusLab/scala-cli/blob/a7b887a45fadc158cafa37a14dcbac8dd0ea36ca/DEV.md?plain=1#L254

carlosedp commented 1 year ago

Last commit to my sample app added some missing reflection/proxy classes: https://github.com/carlosedp/zio-temporal-hello/commit/793d3ec781874b8bc09c7cf459b0ee872480fa27

carlosedp commented 1 year ago

Kinda got a false-positive on https://github.com/vitaliihonta/zio-temporal/issues/91#issuecomment-1620840841 where I've removed all initialization flags replacing by a config to exclude the properties from JARs.

The image was built successfully but once I've tried to access the app's HTTP server (based on zio-http which uses netty) I got the error:

❯ ./out/worker/nativeImage.dest/ziotemporalworker
timestamp=2023-07-12T18:19:58.639298-03:00 level=INFO thread=zio-fiber-6 message="HTTP Metrics Server started at http://localhost:8082/metrics" source=<empty>.Main.run
timestamp=2023-07-12T18:19:58.63969-03:00  level=INFO thread=zio-fiber-6 message="Started sample-worker listening to queue echo-queue" source=<empty>.Worker
timestamp=2023-07-12T18:19:58.670852-03:00 level=INFO thread=zio-fiber-6 message="ZWorkerFactory started" source=zio.temporal.worker.ZWorkerFactory
timestamp=2023-07-12T18:24:37.391004-03:00 level=WARN thread=zio-fiber-785 message="An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception." cause=Exception in thread "zio-fiber-" java.lang.ExceptionInInitializerError: null
    at io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:417)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.kqueue.AbstractKQueueServerChannel$KQueueServerSocketUnsafe.readReady(AbstractKQueueServerChannel.java:112)
    at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.readReady(AbstractKQueueChannel.java:387)
    at io.netty.channel.kqueue.KQueueEventLoop.processReady(KQueueEventLoop.java:213)
    at io.netty.channel.kqueue.KQueueEventLoop.run(KQueueEventLoop.java:291)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base@17.0.7/java.lang.Thread.run(Thread.java:833)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:775)
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:203)
    Suppressed: java.lang.IllegalArgumentException: Can't find '[touch]' in io.netty.util.ReferenceCountUtil
        at io.netty.util.ResourceLeakDetector.addExclusions(ResourceLeakDetector.java:596)
        at io.netty.util.ReferenceCountUtil.<clinit>(ReferenceCountUtil.java:31)
        at io.netty.channel.DefaultChannelPipeline.touch(DefaultChannelPipeline.java:116)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:417)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.kqueue.AbstractKQueueServerChannel$KQueueServerSocketUnsafe.readReady(AbstractKQueueServerChannel.java:112)
        at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.readReady(AbstractKQueueChannel.java:387)
        at io.netty.channel.kqueue.KQueueEventLoop.processReady(KQueueEventLoop.java:213)
        at io.netty.channel.kqueue.KQueueEventLoop.run(KQueueEventLoop.java:291)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base@17.0.7/java.lang.Thread.run(Thread.java:833)
        at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:775)
        at org.graalvm.nativeimage.builder/com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:203) source=io.netty.channel.DefaultChannelPipeline

And the app doesn't respond of return the HTTP request. Weird because the temporal requests are processed and the issue only happens once http is used Back to step 0.

thomaswue commented 1 year ago

Are you using the default metadata for Netty as available at https://github.com/oracle/graalvm-reachability-metadata/tree/master/metadata/io.netty/netty-common? What Netty version are you using?

The error indicates that there is a missing reflection entry for:

{
    "condition": {
      "typeReachable": "io.netty.util.ReferenceCountUtil"
    },
    "name": "io.netty.util.ReferenceCountUtil",
    "queryAllDeclaredMethods": true
}

Netty uses a lot of complex reflection in static constructors. If you initialize those classes at build time, the configuration is not required. It is still recommended to rather configure than initialize at build time.

carlosedp commented 1 year ago

Oh that was it... the issue is that zio-http uses netty-common version 4.1.93 and the metadata has 4.1.80.

I've manually generated the metadata using the native-image-agent updating the existing metadata and it worked!

Another thing I should add to my end-to-end tests to generate http requests so the metadata is generated automatically.

Thanks Thomas!

carlosedp commented 1 year ago

Tried to consolidate the steps I use to generate all metadata for GraalVM in my project: https://github.com/carlosedp/zio-temporal-hello/issues/5

thomaswue commented 1 year ago

OK, cool! Starting from netty 5, the metadata is directly included in the netty JAR file itself to avoid that problem. Can you maybe create a pull request at https://github.com/oracle/graalvm-reachability-metadata with the 4.1.93 netty data?

guizmaii commented 1 year ago

FYI, the Agent way is not working for me, nor the graalvm-reachability-metadata way, nor the combination of both (copying the *-config.json from the metadata repo and then running the Agent to update the copied configs). My extremely minimal project refuses to compile with these settings

I only have 2 dependencies: Netty (4.1.94, inherited from zio-http) and Logback

What is "working" is to use these native-image options: native-image --no-fallback ... --initialize-at-run-time=io.netty --initialize-at-build-time=org.slf4j,ch.qos.logback It's "working" because it's compiling the code and generating the executable binary but my program crashes when it's using Netty at runtime. My program is a CLI. I can launch some commands of the CLI but the ones involving Netty crashes with the following error:

$ ./my-cli say-hello
00:52:29.427 [ZScheduler-Worker-10] ERROR zio-slf4j-logger - 
java.lang.ExceptionInInitializerError: null
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at io.netty.util.internal.PlatformDependent$Mpsc.newMpscQueue(PlatformDependent.java:1029)
        at io.netty.util.internal.PlatformDependent.newMpscQueue(PlatformDependent.java:1040)
        at io.netty.channel.nio.NioEventLoop.newTaskQueue0(NioEventLoop.java:283)
        at io.netty.channel.nio.NioEventLoop.newTaskQueue(NioEventLoop.java:154)
Caused by: java.lang.RuntimeException: java.lang.NoSuchFieldException: producerIndex
        at io.netty.util.internal.shaded.org.jctools.util.UnsafeAccess.fieldOffset(UnsafeAccess.java:111)
        at io.netty.util.internal.shaded.org.jctools.queues.BaseMpscLinkedArrayQueueProducerFields.<clinit>(BaseMpscLinkedArrayQueue.java:55)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at io.netty.util.internal.PlatformDependent$Mpsc.newMpscQueue(PlatformDependent.java:1029)
        at io.netty.util.internal.PlatformDependent.newMpscQueue(PlatformDependent.java:1040)
Caused by: java.lang.NoSuchFieldException: producerIndex
        at java.base@20.0.1/java.lang.Class.checkField(DynamicHub.java:1004)
        at java.base@20.0.1/java.lang.Class.getDeclaredField(DynamicHub.java:1119)
        at io.netty.util.internal.shaded.org.jctools.util.UnsafeAccess.fieldOffset(UnsafeAccess.java:107)
        at io.netty.util.internal.shaded.org.jctools.queues.BaseMpscLinkedArrayQueueProducerFields.<clinit>(BaseMpscLinkedArrayQueue.java:55)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)
        at java.base@20.0.1/java.lang.Class.ensureInitialized(DynamicHub.java:579)

Any idea how to fix this @thomaswue @carlosedp maybe? 🤔

carlosedp commented 1 year ago

The usage of graalvm-reachability-metadata highly depends on the version of the lib. It won't help with zio-http since the metadata added to the repo is for netty 4.1.80 and zio-http uses a newer one. Also the lib only adds the proxy and reflection metadata.

The crash at runtime is because the reflection/proxy metadata is missing and netty requires them. You need to generate with the agent.

Now on to the initialization, what happens is that netty/logback changes some initialization to build-time in it's own metadata so you might need to override or ignore it like I did in my app here: https://github.com/carlosedp/zio-temporal-hello/blob/32adb3de5f0e724833e3a1bb28089d9f50fb8b0c/build.sc#L74C7-L74C7

If you have the link to the sample app, I could look at it to help :) I'll also try to make a sample zio-http/logback app that works and builds with scala-cli.

carlosedp commented 1 year ago

There you go @guizmaii ... a sample app with zio-http and logback which can generate a native-image... I added all configuration needed in the scala file itself so it can be run with scala-cli.

https://gist.github.com/carlosedp/6547bc730899995683442916bb225876

guizmaii commented 1 year ago

@carlosedp what is this configuration for/about -Djdk.http.auth.tunneling.disabledSchemes=? 🤔

Edit: 😖

[info] /Users/jules/.sdkman/candidates/java/20.0.1-graal/bin/native-image --exclude-config .*.jar,.*.properties -cp /Users/jules/workspace/myproject/modules/cli/target/native-image-internal/manifest.jar --no-fallback --enable-http --enable-https --enable-url-protocols=http,https --enable-sbom --install-exit-handlers --diagnostics-mode -H:+BuildReport -H:ConfigurationFileDirectories=/Users/jules/workspace/myproject/modules/cli/src/main/resources/META-INF/native-image io.myproject.cli.CLI /Users/jules/workspace/myproject/cli
# Diagnostics mode enabled: image-build reports are saved to reports/diagnostics_20230718_110258
Error: Unrecognized option: --exclude-config .*.jar,.*.properties
[error] native-image command failed with exit code '20'
[error] (cli / nativeImage) native-image command failed with exit code '20'

Edit 2: Not sure it's equivalent but with -H:ExcludeResources=.*.jar,.*.properties the native-image cmd is at least running

Edit 3: After having run the Agent and have some configurations generated in the /Users/jules/workspace/myproj/modules/cli/src/main/resources/META-INF/native-image directory

[info] /Users/jules/.sdkman/candidates/java/20.0.1-graal/bin/native-image -cp /Users/jules/workspace/myproj/modules/cli/target/native-image-internal/manifest.jar --no-fallback --enable-http --enable-https --enable-url-protocols=http,https --enable-sbom --install-exit-handlers --diagnostics-mode -H:+BuildReport -H:ExcludeResources=.*.jar,.*.properties -H:ConfigurationFileDirectories=/Users/jules/workspace/myproj/modules/cli/src/main/resources/META-INF/native-image io.myproj.cli.CLI /Users/jules/workspace/myproj/cli

fails with:

Error: Classes that should be initialized at run time got initialized during image building:
 ch.qos.logback.classic.Logger was unintentionally initialized at build time. To see why ch.qos.logback.classic.Logger got initialized use --trace-class-initialization=ch.qos.logback.classic.Logger
ch.qos.logback.core.hook.DefaultShutdownHook was unintentionally initialized at build time. To see why ch.qos.logback.core.hook.DefaultShutdownHook got initialized use --trace-class-initialization=ch.qos.logback.core.hook.DefaultShutdownHook
io.netty.channel.DefaultFileRegion the class was requested to be initialized at run time (subtype of io.netty.util.AbstractReferenceCounted). To see why io.netty.channel.DefaultFileRegion got initialized use --trace-class-initialization=io.netty.channel.DefaultFileRegion
org.slf4j.LoggerFactory was unintentionally initialized at build time. To see why org.slf4j.LoggerFactory got initialized use --trace-class-initialization=org.slf4j.LoggerFactory
ch.qos.logback.core.status.StatusBase was unintentionally initialized at build time. To see why ch.qos.logback.core.status.StatusBase got initialized use --trace-class-initialization=ch.qos.logback.core.status.StatusBase
ch.qos.logback.core.util.Duration was unintentionally initialized at build time. To see why ch.qos.logback.core.util.Duration got initialized use --trace-class-initialization=ch.qos.logback.core.util.Duration
io.netty.util.AbstractReferenceCounted the class was requested to be initialized at run time (from 'META-INF/native-image/io.netty/netty-common/native-image.properties' in 'file:///Users/jules/Library/Caches/Coursier/v1/https/repo1.maven.org/maven2/io/netty/netty-common/4.1.94.Final/netty-common-4.1.94.Final.jar' with 'io.netty.util.AbstractReferenceCounted'). To see why io.netty.util.AbstractReferenceCounted got initialized use --trace-class-initialization=io.netty.util.AbstractReferenceCounted
ch.qos.logback.core.status.InfoStatus was unintentionally initialized at build time. To see why ch.qos.logback.core.status.InfoStatus got initialized use --trace-class-initialization=ch.qos.logback.core.status.InfoStatus
To see how the classes got initialized, use --trace-class-initialization=ch.qos.logback.classic.Logger,ch.qos.logback.core.hook.DefaultShutdownHook,io.netty.channel.DefaultFileRegion,org.slf4j.LoggerFactory,ch.qos.logback.core.status.StatusBase,ch.qos.logback.core.util.Duration,io.netty.util.AbstractReferenceCounted,ch.qos.logback.core.status.InfoStatus
com.oracle.svm.core.util.UserError$UserException: Classes that should be initialized at run time got initialized during image building:
 ch.qos.logback.classic.Logger was unintentionally initialized at build time. To see why ch.qos.logback.classic.Logger got initialized use --trace-class-initialization=ch.qos.logback.classic.Logger
ch.qos.logback.core.hook.DefaultShutdownHook was unintentionally initialized at build time. To see why ch.qos.logback.core.hook.DefaultShutdownHook got initialized use --trace-class-initialization=ch.qos.logback.core.hook.DefaultShutdownHook
io.netty.channel.DefaultFileRegion the class was requested to be initialized at run time (subtype of io.netty.util.AbstractReferenceCounted). To see why io.netty.channel.DefaultFileRegion got initialized use --trace-class-initialization=io.netty.channel.DefaultFileRegion
org.slf4j.LoggerFactory was unintentionally initialized at build time. To see why org.slf4j.LoggerFactory got initialized use --trace-class-initialization=org.slf4j.LoggerFactory
ch.qos.logback.core.status.StatusBase was unintentionally initialized at build time. To see why ch.qos.logback.core.status.StatusBase got initialized use --trace-class-initialization=ch.qos.logback.core.status.StatusBase
ch.qos.logback.core.util.Duration was unintentionally initialized at build time. To see why ch.qos.logback.core.util.Duration got initialized use --trace-class-initialization=ch.qos.logback.core.util.Duration
io.netty.util.AbstractReferenceCounted the class was requested to be initialized at run time (from 'META-INF/native-image/io.netty/netty-common/native-image.properties' in 'file:///Users/jules/Library/Caches/Coursier/v1/https/repo1.maven.org/maven2/io/netty/netty-common/4.1.94.Final/netty-common-4.1.94.Final.jar' with 'io.netty.util.AbstractReferenceCounted'). To see why io.netty.util.AbstractReferenceCounted got initialized use --trace-class-initialization=io.netty.util.AbstractReferenceCounted
ch.qos.logback.core.status.InfoStatus was unintentionally initialized at build time. To see why ch.qos.logback.core.status.InfoStatus got initialized use --trace-class-initialization=ch.qos.logback.core.status.InfoStatus
To see how the classes got initialized, use --trace-class-initialization=ch.qos.logback.classic.Logger,ch.qos.logback.core.hook.DefaultShutdownHook,io.netty.channel.DefaultFileRegion,org.slf4j.LoggerFactory,ch.qos.logback.core.status.StatusBase,ch.qos.logback.core.util.Duration,io.netty.util.AbstractReferenceCounted,ch.qos.logback.core.status.InfoStatus
    at org.graalvm.nativeimage.builder/com.oracle.svm.core.util.UserError.abort(UserError.java:73)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ProvenSafeClassInitializationSupport.checkDelayedInitialization(ProvenSafeClassInitializationSupport.java:277)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.classinitialization.ClassInitializationFeature.duringAnalysis(ClassInitializationFeature.java:164)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGenerator.lambda$runPointsToAnalysis$10(NativeImageGenerator.java:770)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.FeatureHandler.forEachFeature(FeatureHandler.java:86)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGenerator.lambda$runPointsToAnalysis$11(NativeImageGenerator.java:770)
    at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.AbstractAnalysisEngine.runAnalysis(AbstractAnalysisEngine.java:179)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGenerator.runPointsToAnalysis(NativeImageGenerator.java:767)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:582)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGenerator.run(NativeImageGenerator.java:539)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.buildImage(NativeImageGeneratorRunner.java:408)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.build(NativeImageGeneratorRunner.java:612)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.start(NativeImageGeneratorRunner.java:134)
    at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.main(NativeImageGeneratorRunner.java:94)

Edit 4: I made a reproducer here: https://github.com/gnp/zio-quickstart-https/pull/1 You can see that the native-image configs have been generated in modules/cli/src/main/resources/META-INF/native-image, yet the CLI module fails to natively compile 🤷‍♂️

Edit 5: Parsing of the --exclude-config option seems to be broken https://github.com/oracle/graal/issues/7010

carlosedp commented 1 year ago

Apparently you are using Graal 20 and the --exclude-config is available from Graal 23.

The "Classes that should be initialized at run time got initialized during image building" error is because netty and/or logback are initializing some classes at build-time with their own metadata, the exclude-config should override this. Also you don't need the --initialize-at-runtime anymore with it since initialization on runtime is default for all classes.

According to Oracle docs, the -Djdk.http.auth.tunneling.disabledSchemes is:

Disable Basic authentication for HTTPS tunneling In some environments, certain authentication schemes may be undesirable when proxying HTTPS. Accordingly, the Basic authentication scheme has been deactivated, by default, in the Oracle Java Runtime, by adding Basic to the jdk.http.auth.tunneling.disabledSchemes networking property. Now, proxies requiring Basic authentication when setting up a tunnel for HTTPS will no longer succeed by default. If required, this authentication scheme can be reactivated by removing Basic from the jdk.http.auth.tunneling.disabledSchemes networking property, or by setting a system property of the same name to "" ( empty ) on the command line.

Check my Gist, it contains the basics to make it all work with both logback and zio-http (which uses netty).