Quarkus: Using OpenCensus with Quarkus produces NullPointerException in native image

Created on 4 May 2020  路  26Comments  路  Source: quarkusio/quarkus

Bug Description
Using OpenCensus 0.26 with Quarkus 1.4.1.Final in native image produces a NullPointerException when using the io.opencensus.trace.Tracer.

Expected behavior
The Tracing should work.

Actual behavior
Using OpenCensus 0.26 with Quarkus 1.4.1.Final in native image produces a NullPointerException when using the io.opencensus.trace.Tracer.

2020-05-04 18:40:27,175 ERROR [com.deu.gcp.exc.DefaultExceptionHandler] (executor-thread-1) DefaultExceptionHandler processing exception: java.lang.NullPointerException at io.opencensus.impl.internal.DisruptorEventQueue$1.enqueue(DisruptorEventQueue.java:137) at io.opencensus.impl.internal.DisruptorEventQueue.enqueue(DisruptorEventQueue.java:162) at io.opencensus.implcore.trace.StartEndHandlerImpl.onEnd(StartEndHandlerImpl.java:72) at io.opencensus.implcore.trace.RecordEventsSpanImpl.end(RecordEventsSpanImpl.java:384) at io.opencensus.trace.Span.end(Span.java:244) at io.opencensus.trace.CurrentSpanUtils$ScopeInSpan.close(CurrentSpanUtils.java:100)

During the native image build, a warning is printed

Warning: RecomputeFieldValue.ArrayIndexScale automatic substitution failed. The automatic substitution registration was attempted because a call to jdk.internal.misc.Unsafe.arrayIndexScale(Class) was detected in the static initializer of com.lmax.disruptor.RingBufferFields. Detailed failure reason(s): Could not determine the field where the value produced by the call to jdk.internal.misc.Unsafe.arrayIndexScale(Class) for the array index scale computation is stored. The call is not directly followed by a field store or by a sign extend node followed directly by a field store.

To Reproduce
Steps to reproduce the behavior:

  1. Clone the extension (git clone https://github.com/thankthemaker/quarkus-opencensus-extension)
  2. Build the extension (mvn clean install)
  3. Clone the example app (git clone https://github.com/thankthemaker/opencensus-example)
  4. Build the native image (mvn clean package -Pnative)
  5. watch out for the warnings during native image build
  6. run the native image (./target/opencensus-example-1.0.0-SNAPSHOT-runner)
  7. make a request to the hello endpoint (e.g. curl localhost:8080/hello)
  8. watch out for the NullPointerException, produced at io.opencensus.impl.internal.DisruptorEventQueue$1.enqueue(DisruptorEventQueue.java:137)
    R

Configuration

# Add your application.properties here, if applicable.

Screenshots
(If applicable, add screenshots to help explain your problem.)

Environment (please complete the following information):
Darwin Kernel Version 19.3.0: Thu Jan 9 20:58:23 PST 2020; root:xnu-6153.81.5~1/RELEASE_X86_64 x86_64

openjdk version "11.0.6" 2020-01-14
OpenJDK Runtime Environment GraalVM CE 20.0.0 (build 11.0.6+9-jvmci-20.0-b02)
OpenJDK 64-Bit Server VM GraalVM CE 20.0.0 (build 11.0.6+9-jvmci-20.0-b02, mixed mode, sharing)

Quarkus version 1.4.1.Final:

Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: /Users/dgey/apache-maven-3.6.3
Java version: 11.0.6, vendor: Oracle Corporation, runtime: /Users/dgey/graalvm-ce-java11-20.0.0/Contents/Home
Default locale: de_DE, platform encoding: UTF-8
OS name: "mac os x", version: "10.15.3", arch: "x86_64", family: "mac"

kinextension-proposal
Source
picture thankthemaker

Most helpful comment

Slight tangent, but we're beginning to work on OpenTelemetry for Quarkus and SmallRye, which is the replacement for OpenCensus.

picture kenfinnigan on 2 Jun 2020
👍2

All 26 comments

We don't have an OpenCensus extension, so I would say that things like this would be expected.

However it would be nice to see a contribution in this area.

geoand picture geoand on 4 May 2020

Ok, I also tried to build it as an extension. I get exactly the same error when using the extension in my Quarkus application. What am I doing wrong?

thankthemaker picture thankthemaker on 5 May 2020

If you want to build an extension for OpenCensus, I propose you read:

https://quarkus.io/guides/writing-extensions
https://quarkus.io/guides/writing-native-applications-tips

geoand picture geoand on 5 May 2020

I already read both guides before opening the issue and tried to implement an extension based on the information of the guides. I'll try to provide you my code.

thankthemaker picture thankthemaker on 5 May 2020

So, I pushed my example extension and an example project to github. I hope this helps to give me a hint how to solve the NullPointerException

Steps to reproduce:

  1. Clone the extension (git clone https://github.com/thankthemaker/quarkus-opencensus-extension)
  2. Build the extension (mvn clean install)
  3. Clone the example app (git clone https://github.com/thankthemaker/opencensus-example)
  4. Build the native image (mvn clean package -Pnative)
  5. watch out for the warnings during native image build
  6. run the native image (./target/opencensus-example-1.0.0-SNAPSHOT-runner)
  7. make a request to the hello endpoint (e.g. curl localhost:8080/hello)
  8. watch out for the NullPointerException, produced at io.opencensus.impl.internal.DisruptorEventQueue$1.enqueue(DisruptorEventQueue.java:137)
2020-05-05 08:34:00,240 INFO  [io.quarkus] (main) opencensus-example 1.0.0-SNAPSHOT (powered by Quarkus 1.4.1.Final) started in 0.146s. Listening on: http://0.0.0.0:8080
2020-05-05 08:34:00,243 INFO  [io.quarkus] (main) Profile prod activated. 
2020-05-05 08:34:00,243 INFO  [io.quarkus] (main) Installed features: [cdi, opencensus-extension, resteasy, resteasy-jsonb]
2020-05-05 08:34:03,847 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /hello failed, error id: 5fc6d6a8-afcc-4e07-be77-045726ef5258-1: org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:106)
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:372)
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:216)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:515)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:259)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:160)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:362)
        at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:163)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:245)
        at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:123)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:36)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:87)
        at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
        at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at java.lang.Thread.run(Thread.java:834)
        at org.jboss.threads.JBossThread.run(JBossThread.java:479)
        at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:527)
        at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
Caused by: java.lang.NullPointerException
        at io.opencensus.impl.internal.DisruptorEventQueue$1.enqueue(DisruptorEventQueue.java:137)
        at io.opencensus.impl.internal.DisruptorEventQueue.enqueue(DisruptorEventQueue.java:162)
        at io.opencensus.implcore.trace.StartEndHandlerImpl.onEnd(StartEndHandlerImpl.java:72)
        at io.opencensus.implcore.trace.RecordEventsSpanImpl.end(RecordEventsSpanImpl.java:384)
        at io.opencensus.trace.Span.end(Span.java:244)
        at org.thankthemaker.quarkus.logging.TraceInterceptor.logTraceAndContinue(TraceInterceptor.java:112)
        at org.thankthemaker.quarkus.logging.TraceInterceptor.createSpanForRequestAndContinue(TraceInterceptor.java:68)
        at org.thankthemaker.quarkus.logging.TraceInterceptor.traceMethodInvocation(TraceInterceptor.java:46)
        at org.thankthemaker.quarkus.logging.TraceInterceptor_Bean.intercept(TraceInterceptor_Bean.zig:95)
        at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
        at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
        at org.thankthemaker.quarkus.ExampleResource_Subclass.hello(ExampleResource_Subclass.zig:72)
        at java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
        at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:621)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:487)
        at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:437)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:362)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:439)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:400)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:374)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:67)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:488)
        ... 19 more

Running the example application in JVM mode works like charm.

thankthemaker picture thankthemaker on 5 May 2020

Just by eye-balling the disruptor code it it's not evident what the problem could be. This would likely require some serious analysis and perhaps some upstream changes.

geoand picture geoand on 5 May 2020

Could you expand on the Warning during the native image build I posted in the initial comment? For me it looks like the native image build the GraalVM can't handle whatever the RingBuffer stuff does.

I saw there's also a opencensus-impl-lite library. I'll give this a try.

thankthemaker picture thankthemaker on 5 May 2020

It looks like RingBuffer is doing some stuff with sun.misc.Unsafe: https://github.com/LMAX-Exchange/disruptor/blob/master/src/main/java/com/lmax/disruptor/RingBuffer.java#L38

IIRC, Netty did similar things, and we have a whole bunch of GraalVM substitutions for that to work. See https://github.com/quarkusio/quarkus/blob/c4c8b6048b922a0873d4e4f77bcc2c0d96325a24/extensions/netty/runtime/src/main/java/io/quarkus/netty/runtime/graal/NettySubstitutions.java

geoand picture geoand on 5 May 2020
👍1

Cool, thanks for the hint. I will have a look at that, never dealed with substitutions before.

thankthemaker picture thankthemaker on 5 May 2020
👍1

Our netty extension probably does the most complicated substitutions, so it should be a great place to get inspiration from.

geoand picture geoand on 5 May 2020
👍1

I'm already looking at the netty-extension. Not quite easy to understand if you're new to GraalVM sustitutions and even sun.misc.Unsafe. Seems I'll first have to do some homework ;-)

thankthemaker picture thankthemaker on 5 May 2020

Make sure to also re-read the links I added above as you go through the code, because a lot of that stuff doesn't make much sense until you actually see it in action :wink:

geoand picture geoand on 5 May 2020

Ok, I'll do so. Thanks!

thankthemaker picture thankthemaker on 5 May 2020

Sure thing!

geoand picture geoand on 5 May 2020

Ok, I implemented two substitutions like you guys did in the netty extension. I also pushed the changes to https://github.com/thankthemaker/quarkus-opencensus-extension/tree/f-substitutions

final class UnsafeAccessSubstitution {}

@TargetClass(className = "com.lmax.disruptor.RingBufferFields")
final class Target_com_lmax_disruptor_RingBufferFields {
    @Alias
    @RecomputeFieldValue(kind = RecomputeFieldValue.Kind.FieldOffset, name = "REF_ARRAY_BASE")
    private static long REF_ARRAY_BASE;

    @Alias
    @RecomputeFieldValue(kind = RecomputeFieldValue.Kind.ArrayIndexShift, declClass = Object[].class, name = "REF_ELEMENT_SHIFT")
    public static int REF_ELEMENT_SHIFT;
}

Now I'm facing this error. 

Fatal error: jdk.vm.ci.common.JVMCIError: should not reach here: Unsafe access of static fields is not supported.
        at jdk.internal.vm.ci/jdk.vm.ci.common.JVMCIError.shouldNotReachHere(JVMCIError.java:48)
        at com.oracle.graal.pointsto.meta.AnalysisField.registerAsUnsafeAccessed(AnalysisField.java:267)
        at com.oracle.graal.pointsto.meta.AnalysisField.registerAsUnsafeAccessed(AnalysisField.java:261)
        at com.oracle.svm.hosted.substitute.AnnotationSubstitutionProcessor.processComputedValueFields(AnnotationSubstitutionProcessor.java:216)
        at com.oracle.svm.hosted.NativeImageGenerator.initializeBigBang(NativeImageGenerator.java:923)
        at com.oracle.svm.hosted.NativeImageGenerator.setupNativeImage(NativeImageGenerator.java:852)
        at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:528)
        at com.oracle.svm.hosted.NativeImageGenerator.lambda$run$0(NativeImageGenerator.java:445)
        at java.base/java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1407)
        at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
        at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
        at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
        at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
        at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
Error: Image build request failed with exit status 1

Any hints on what I've to do to substitute the static fields? What am I doing wrong?

thankthemaker picture thankthemaker on 5 May 2020

Doesn't ring a bell. @dmlloyd or @cescoffier perhaps?

geoand picture geoand on 5 May 2020

Is the code trying to access to the substituted fields using Unsafe?

cescoffier picture cescoffier on 5 May 2020

Hi,
I'm using the OpenCensus Tracer which keeps it's spans in a com.lmax.disruptor.RingBuffer.
The RingBuffer itself defines some static fields, which get initialized using sun.misc.Unsafe

    {
        final int scale = UNSAFE.arrayIndexScale(Object[].class);
        if (4 == scale)
        {
            REF_ELEMENT_SHIFT = 2;
        }
        else if (8 == scale)
        {
            REF_ELEMENT_SHIFT = 3;
        }
        else
        {
            throw new IllegalStateException("Unknown pointer size");
        }
        BUFFER_PAD = 128 / scale;
        // Including the buffer pad in the array base offset
        REF_ARRAY_BASE = UNSAFE.arrayBaseOffset(Object[].class) + 128;
    }

I tried to substitute these fields as recommended by @geoand following the same approach which is used in the netty-extension.

thankthemaker picture thankthemaker on 5 May 2020

The message seems to be clear: you can't access static fields via unsafe for some reason. Instead maybe create a singleton class and substitute the accesses to those fields with methods that access the instance fields instead.

dmlloyd picture dmlloyd on 5 May 2020

Could you maybe point me to an example? I haven't understood completely what your approach looks like.

thankthemaker picture thankthemaker on 5 May 2020

Any hint?

thankthemaker picture thankthemaker on 6 May 2020

I don't know of any examples of doing this exact thing, but there are plenty of examples in the Quarkus and GraalVM code bases of using @Substitute and @InjectAccessors which would hopefully be sufficient to piece it together. Check out the GraalVM documentation for those annotations as well.

dmlloyd picture dmlloyd on 6 May 2020
👍1

Slight tangent, but we're beginning to work on OpenTelemetry for Quarkus and SmallRye, which is the replacement for OpenCensus.

kenfinnigan picture kenfinnigan on 2 Jun 2020
👍2

Looking forward to use it!

thankthemaker picture thankthemaker on 2 Jun 2020

Slight tangent, but we're beginning to work on OpenTelemetry for Quarkus and SmallRye, which is the replacement for OpenCensus.

Is there a place where we could track the progress of this? I believe it might open up the path to integrating with Google Cloud Trace. Thanks!

kostacasa picture kostacasa on 3 Jul 2020

I've created https://github.com/quarkusio/quarkus/issues/10499 to track the work on the Quarkus side, but there are also things happening in SmallRye for it too

kenfinnigan picture kenfinnigan on 6 Jul 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

gastaldi picture gastaldi  路  3Comments
rsvoboda picture rsvoboda  路  3Comments
nderwin picture nderwin  路  3Comments
lburgazzoli picture lburgazzoli  路  3Comments
blsouthr picture blsouthr  路  3Comments