Re-enable OpenTelemetryQuartzIT and OpenTelemetrySchedulerIT

mkouba commented 10 months ago

Description

This is a follow-up of https://github.com/quarkusio/quarkus/pull/35989.

Implementation ideas

No response

quarkus-bot[bot] commented 10 months ago

/cc @brunobat (opentelemetry), @machi1990 (quartz), @radcortez (opentelemetry)

mkouba commented 10 months ago

CC @mskacelik

mskacelik commented 10 months ago

Gonna have a look at it.

brunobat commented 9 months ago

any news on this, @mskacelik?

mskacelik commented 9 months ago

Hi @brunobat, I haven't started it yet; I wanted to wait for you after your PTO. The issue is with the native Quarkus tests. The generated spans, containing information about a specific error (exception), are missing several fields compared to the JVM tests. Interestingly, when I attempted to replicate this on a Quarkus application, these fields were present even in native mode (checked in Jaeger). I will sent you a dm.

mkouba commented 4 weeks ago

@mskacelik Any update on this issue?

brunobat commented 4 weeks ago

This is probably related with this class: https://github.com/quarkusio/quarkus/blob/6c76604345e691cea5c5224ca1db6d37dd9a44d7/integration-tests/opentelemetry/src/main/java/io/quarkus/it/opentelemetry/output/SpanDataSerializer.java

mskacelik commented 4 weeks ago

@mskacelik Any update on this issue?

Hi @mkouba I found that for these two representations of the SpanData instance during native mode (one with raw SpanData via toString and the second is the serialized representation of SpanData).

List<SpanData> instance: https://github.com/quarkusio/quarkus/blob/8012cf53931cc02f4ba95eb78f4ec2e66143bbc2/integration-tests/opentelemetry-quartz/src/main/java/io/quarkus/it/opentelemetry/quartz/ExporterResource.java#L21-L28

SpanData{spanContext=ImmutableSpanContext{traceId=dd648ce9747cb5ce5efe9bc3e3d7ca09, spanId=11ab721cc76251d4, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, resource=Resource{schemaUrl=https://opentelemetry.io/schemas/1.21.0, attributes={host.name="mskaceli-mac", service.name="quarkus-integration-test-opentelemetry-quartz", service.version="999-SNAPSHOT", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.31.0", webengine.name="Quarkus", webengine.version="999-SNAPSHOT"}}, instrumentationScopeInfo=InstrumentationScopeInfo{name=io.quarkus.opentelemetry, version=null, schemaUrl=null, attributes={}}, name=myFailedBasicScheduler, kind=INTERNAL, startEpochNanos=1707482727615446000, endEpochNanos=1707482727719361459, attributes={}, totalAttributeCount=0, events=[ImmutableExceptionEventData{epochNanos=1707482727719359917, exception=java.util.concurrent.CompletionException: java.lang.RuntimeException: error occurred in myFailedBasicScheduler., additionalAttributes={}, spanLimits=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=}, hasEnded=true}

Map<String, Object> entry (serialized SpanData): https://github.com/quarkusio/quarkus/blob/8012cf53931cc02f4ba95eb78f4ec2e66143bbc2/integration-tests/opentelemetry-quartz/src/test/java/io/quarkus/it/opentelemetry/quartz/OpenTelemetryQuartzTest.java#L70-L73

{kind=INTERNAL, name=myFailedBasicScheduler, resource={attributes={empty=false}, schemaUrl=https://opentelemetry.io/schemas/1.21.0}, attributes={empty=true}, instrumentationLibraryInfo={version=null, name=io.quarkus.opentelemetry, schemaUrl=null}, instrumentationScopeInfo={version=null, name=io.quarkus.opentelemetry, attributes={empty=true}, schemaUrl=null}, status={statusCode=ERROR, description=}, parentSpanContext={valid=false, traceFlags={sampled=false}, traceIdBytes=AAAAAAAAAAAAAAAAAAAAAA==, spanIdBytes=AAAAAAAAAAA=, traceState={empty=true}, traceId=00000000000000000000000000000000, spanId=0000000000000000, sampled=false, remote=false}, parentSpanId=0000000000000000, endEpochNanos=1707482727719361459, totalRecordedEvents=1, totalRecordedLinks=0, spanContext={valid=true, traceFlags={sampled=true}, traceIdBytes=3WSM6XR8tc5e/pvD49fKCQ==, spanIdBytes=EatyHMdiUdQ=, traceState={empty=true}, traceId=dd648ce9747cb5ce5efe9bc3e3d7ca09, spanId=11ab721cc76251d4, sampled=true, remote=false}, totalAttributeCount=0, startEpochNanos=1707482727615446000, traceId=dd648ce9747cb5ce5efe9bc3e3d7ca09, spanId=11ab721cc76251d4, events=[{name=exception, attributes={empty=false}, epochNanos=1707482727719359917, totalAttributeCount=3, droppedAttributesCount=0}], links=[]}

These two representations differ in some fields/attributes, especially the second representation misses all the information about the thrown exception (spanIDs are the same).

So, I hypothesized that the serialization process does not work (in native mode); I tried adding a @RegisterForReflection annotation for some classes (like ImmutableExceptionEventData) or adding configuration properties for entire extensions. But nothing worked :-/.

mskacelik commented 2 weeks ago

Ok, I found something interesting.

Only the events field behaves differently. All the other fields are exactly the same (for all combinations failing/non-failing with JVM/native).

For the event field here are all the possibilities in the tests (the spans that contain Exception, since those do not work):

JVM tets

Before the serialization (`SpanData#toString`):

events=[ImmutableExceptionEventData{epochNanos=1728311743120525209, exception=java.util.concurrent.CompletionException: java.lang.RuntimeException: error occurred in myFailedBasicScheduler., additionalAttributes={}, spanLimits=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}}]

After the serialization (`Map.Entry<String, Object>#toString`):

The entire `events` block (large due to stacktrace)

`events=[{epochNanos=1728311743120525209, exception={cause={cause=null, stackTrace=[{classLoaderName=null, moduleName=null, moduleVersion=null, methodName=init, fileName=FailedBasicScheduler.java, lineNumber=13, nativeMethod=false, className=io.quarkus.it.opentelemetry.quartz.FailedBasicScheduler}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=init, fileName=null, lineNumber=-1, nativeMethod=false, className=io.quarkus.it.opentelemetry.quartz.FailedBasicScheduler_ClientProxy}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invokeBean, fileName=null, lineNumber=-1, nativeMethod=false, className=io.quarkus.it.opentelemetry.quartz.FailedBasicScheduler_ScheduledInvoker_init_c916f7ba9fb930c97469c077dde036af0dab8d5d}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=DefaultInvoker.java, lineNumber=25, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DefaultInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invokeDelegate, fileName=DelegateInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DelegateInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=StatusEmitterInvoker.java, lineNumber=35, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.StatusEmitterInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invokeDelegate, fileName=DelegateInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DelegateInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=executeJob, fileName=InstrumentedInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.InstrumentedInvoker$1}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=instrument, fileName=OpenTelemetryJobInstrumenter.java, lineNumber=50, nativeMethod=false, className=io.quarkus.opentelemetry.runtime.tracing.intrumentation.scheduler.OpenTelemetryJobInstrumenter}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=InstrumentedInvoker.java, lineNumber=24, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.InstrumentedInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=doInvoke, fileName=OffloadingInvoker.java, lineNumber=70, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=call, fileName=OffloadingInvoker.java, lineNumber=52, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker$2}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=call, fileName=OffloadingInvoker.java, lineNumber=49, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker$2}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=lambda$executeBlocking$0, fileName=ContextImpl.java, lineNumber=178, nativeMethod=false, className=io.vertx.core.impl.ContextImpl}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=dispatch, fileName=ContextInternal.java, lineNumber=270, nativeMethod=false, className=io.vertx.core.impl.ContextInternal}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=lambda$internalExecuteBlocking$2, fileName=ContextImpl.java, lineNumber=210, nativeMethod=false, className=io.vertx.core.impl.ContextImpl}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=runWith, fileName=VertxCoreRecorder.java, lineNumber=632, nativeMethod=false, className=io.quarkus.vertx.core.runtime.VertxCoreRecorder$14}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=doRunWith, fileName=EnhancedQueueExecutor.java, lineNumber=2516, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$Task}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=EnhancedQueueExecutor.java, lineNumber=2495, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$Task}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=EnhancedQueueExecutor.java, lineNumber=1495, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$ThreadBody}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=DelegatingRunnable.java, lineNumber=11, nativeMethod=false, className=org.jboss.threads.DelegatingRunnable}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=ThreadLocalResettingRunnable.java, lineNumber=11, nativeMethod=false, className=org.jboss.threads.ThreadLocalResettingRunnable}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=FastThreadLocalRunnable.java, lineNumber=30, nativeMethod=false, className=io.netty.util.concurrent.FastThreadLocalRunnable}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=run, fileName=Thread.java, lineNumber=833, nativeMethod=false, className=java.lang.Thread}], message=error occurred in myFailedBasicScheduler., suppressed=[], localizedMessage=error occurred in myFailedBasicScheduler.}, stackTrace=[{classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=encodeThrowable, fileName=CompletableFuture.java, lineNumber=332, nativeMethod=false, className=java.util.concurrent.CompletableFuture}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=completeThrowable, fileName=CompletableFuture.java, lineNumber=347, nativeMethod=false, className=java.util.concurrent.CompletableFuture}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=uniWhenComplete, fileName=CompletableFuture.java, lineNumber=874, nativeMethod=false, className=java.util.concurrent.CompletableFuture}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=uniWhenCompleteStage, fileName=CompletableFuture.java, lineNumber=887, nativeMethod=false, className=java.util.concurrent.CompletableFuture}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=whenComplete, fileName=CompletableFuture.java, lineNumber=2325, nativeMethod=false, className=java.util.concurrent.CompletableFuture}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=whenComplete, fileName=CompletableFuture.java, lineNumber=2902, nativeMethod=false, className=java.util.concurrent.CompletableFuture$MinimalStage}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=DefaultInvoker.java, lineNumber=25, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DefaultInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invokeDelegate, fileName=DelegateInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DelegateInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=StatusEmitterInvoker.java, lineNumber=35, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.StatusEmitterInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invokeDelegate, fileName=DelegateInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.DelegateInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=executeJob, fileName=InstrumentedInvoker.java, lineNumber=28, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.InstrumentedInvoker$1}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=instrument, fileName=OpenTelemetryJobInstrumenter.java, lineNumber=50, nativeMethod=false, className=io.quarkus.opentelemetry.runtime.tracing.intrumentation.scheduler.OpenTelemetryJobInstrumenter}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=invoke, fileName=InstrumentedInvoker.java, lineNumber=24, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.InstrumentedInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=doInvoke, fileName=OffloadingInvoker.java, lineNumber=70, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=call, fileName=OffloadingInvoker.java, lineNumber=52, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker$2}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=call, fileName=OffloadingInvoker.java, lineNumber=49, nativeMethod=false, className=io.quarkus.scheduler.common.runtime.OffloadingInvoker$2}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=lambda$executeBlocking$0, fileName=ContextImpl.java, lineNumber=178, nativeMethod=false, className=io.vertx.core.impl.ContextImpl}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=dispatch, fileName=ContextInternal.java, lineNumber=270, nativeMethod=false, className=io.vertx.core.impl.ContextInternal}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=lambda$internalExecuteBlocking$2, fileName=ContextImpl.java, lineNumber=210, nativeMethod=false, className=io.vertx.core.impl.ContextImpl}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=runWith, fileName=VertxCoreRecorder.java, lineNumber=632, nativeMethod=false, className=io.quarkus.vertx.core.runtime.VertxCoreRecorder$14}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=doRunWith, fileName=EnhancedQueueExecutor.java, lineNumber=2516, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$Task}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=EnhancedQueueExecutor.java, lineNumber=2495, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$Task}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=EnhancedQueueExecutor.java, lineNumber=1495, nativeMethod=false, className=org.jboss.threads.EnhancedQueueExecutor$ThreadBody}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=DelegatingRunnable.java, lineNumber=11, nativeMethod=false, className=org.jboss.threads.DelegatingRunnable}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=ThreadLocalResettingRunnable.java, lineNumber=11, nativeMethod=false, className=org.jboss.threads.ThreadLocalResettingRunnable}, {classLoaderName=null, moduleName=null, moduleVersion=null, methodName=run, fileName=FastThreadLocalRunnable.java, lineNumber=30, nativeMethod=false, className=io.netty.util.concurrent.FastThreadLocalRunnable}, {classLoaderName=null, moduleName=java.base, moduleVersion=17.0.6, methodName=run, fileName=Thread.java, lineNumber=833, nativeMethod=false, className=java.lang.Thread}], message=java.lang.RuntimeException: error occurred in myFailedBasicScheduler., suppressed=[], localizedMessage=java.lang.RuntimeException: error occurred in myFailedBasicScheduler.}, additionalAttributes={empty=true}, attributes={empty=false}, name=exception, totalAttributeCount=3, droppedAttributesCount=0}]`

Native tests

Before the serialization (`SpanData#toString`):

events=[ImmutableExceptionEventData{epochNanos=1728312313087000875, exception=java.util.concurrent.CompletionException: java.lang.RuntimeException: error occurred in myFailedBasicScheduler., additionalAttributes={}, spanLimits=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}}]

After the serialization (`Map.Entry<String, Object>#toString`):

events=[{attributes={empty=false}, name=exception, droppedAttributesCount=0, epochNanos=1728312313087000875, totalAttributeCount=3}]

All the relevant classes:

https://github.com/open-telemetry/opentelemetry-java/blob/0f859b4385d12be9c0e8a36748813dd7553b46c6/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/data/SpanData.java#L102

https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/data/EventData.java (notice how the fields equal the serialized fields)

https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/internal/data/ImmutableExceptionEventData.java

What have I tried so far:

I tried to have a custom registerforReflection class (similiar to this: https://github.com/quarkusio/quarkus/blob/main/integration-tests/opentelemetry-vertx/src/main/java/io/quarkus/it/opentelemetry/vertx/SpanData.java) (did not work)

I tried adding these configuration properties for explicit class indexing:

quarkus.index-dependency.otelsdk.group-id=io.opentelemetry
quarkus.index-dependency.otelsdk.artifact-id=opentelemetry-sdk
quarkus.index-dependency.otelapi.group-id=io.opentelemetry
quarkus.index-dependency.otelapi.artifact-id=opentelemetry-api

Also did not work.

quarkusio / quarkus