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

Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build while using RESTEasy “controller” based approach #22595

Closed
amitkumar7566 opened this issue Jan 3, 2022 · 55 comments · Fixed by #23038
Labels
area/smallrye area/tracing kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant

Comments

@amitkumar7566
Copy link

amitkumar7566 commented Jan 3, 2022

Describe the bug

I an using "Controller" based approach using RESTEasy. I have added Quarkus AWS Xray dependency in my POM.xml..

And then we are instrumenting calls to AWS Services using below dependency:

com.amazonaws
aws-xray-recorder-sdk-aws-sdk-v2-instrumentor
2.10.0

Also, we create manual sub-segment for external API calls..

However, Quarkus send sub-segment traces to XRay in the JVM build..
But in Native build, it does not send any sub-segments... also, there is no error thrown. In cloudwatch logs, it says "TRACE_ID missing.

It works for native build in AWS Lambda "Handler" based approach but not in "Controller" based approach in RESTEasy.
Attaching the screenshots of JVM and Native Build below:

Expected behavior

It should create and show sub-segments in the graph also.

Actual behavior

It does not show the sub-segments in Native build.

How to Reproduce?

https://github.com/amitkumar7566/xray-native-image-test

Output of uname -a or ver

No response

Output of java -version

java 11

GraalVM version (if different from Java)

21.3-java11

Quarkus version or git rev

2.6.1.Final

Build tool (ie. output of mvnw --version or gradlew --version)

maven

Additional information

No response

@amitkumar7566 amitkumar7566 added the kind/bug Something isn't working label Jan 3, 2022
@quarkus-bot
Copy link

quarkus-bot bot commented Jan 3, 2022

/cc @Ladicek, @radcortez

@gsmet
Copy link
Member

gsmet commented Jan 3, 2022

My guess is that we might need to register something more for reflection. But what... If you can debug in JVM which objects are serialized that contain the information you want, that might help.

@radcortez
Copy link
Member

A reproducer could also help. Thanks!

@amitkumar7566
Copy link
Author

amitkumar7566 commented Jan 4, 2022

@gsmet @radcortez
I am unable to share any reproducer as our code highly restricted.
However, you can create and test a simple hello word application also.. try using dynamodb & also one external api call using your restclient and subsegment that.

We cant see any application for xray in your quarkus-quickstarts repo.
Also, the documentation regarding Xray is not properly detailed in quarkus portal.

@gsmet
Copy link
Member

gsmet commented Jan 4, 2022

Well, if you want it fixed, please provide more information. I don't have the time to set up everything to reproduce it.

Just giving us the name of the classes in AWS Xray containing the missing information would help if you can debug your JVM app and see where they are.

@gsmet gsmet added the triage/needs-reproducer We are waiting for a reproducer. label Jan 4, 2022
@radcortez
Copy link
Member

@amitkumar7566 could you just provide a minimal reproducer? It shouldn't require any of your restricted code. I may be able to look into it since I'm planning to rework the config portion of tracing, but I'm still not there yet.

@amitkumar7566
Copy link
Author

Hi @gsmet @radcortez

Here is a sample reproducer git project repo which has 2 resources covering both of the below types of scenarios:

  1. GET "/books/db" -> Showing the use of an AWS service (DynamoDB).
  2. GET "/books/restclient" -> Showing the use of an External API call using Quarkus REST Client.

Git repo link: https://github.com/amitkumar7566/xray-native-image-test

Here are the findings to help you :-

A. Findings in Normal JVM Build

  1. Calls to AWS DynamoDB automatically gets traced using below maven dependency. In AWS Xray console, a subsegment (DynamoDB) can be seen and it also reflects in the X-ray graph.
<dependency>
    <groupId>com.amazonaws</groupId>
    <artifactId>aws-xray-recorder-sdk-aws-sdk-v2-instrumentor</artifactId>
    <version>2.10.0</version>
</dependency>

1A  JVM Mode - Calls to DynamoDB subsegment traced   appears in Xray graph

  1. Calls to an External API Call gets traced by surrounding the REST Client code block as below. In AWS Xray console, a subsegment (External API Call) can be seen but it DOES NOT reflect in the X-ray graph.
Subsegment subsegment = AWSXRay.beginSubsegment("External API Call");
List<Book> books = restClientService.fetchAll();
AWSXRay.endSubsegment();

1B  JVM Mode - Calls to External API Call subsegment traced but not showing in Xray graph

B. Findings in Native Build

1a. AWS DynamoDB subsegments DOES NOT get traced. In AWS Xray console, neither the subsegment nor the X-ray graph shows anything.
2A 1  NATIVE Build - Calls to DynamoDB subsegment NOT traced   DOES NOT appear in Xray graph

1b. Cloudwatch shows below error message:
2A 2  CloudWatch Logs - DynamoDB Subsegment discarded because of _X_AMZN_TRACE_ID is missing a trace ID, parent ID, or sampling decision

2a. External API Call subsegments DOES NOT get traced. In AWS Xray console, neither the subsegment nor the X-ray graph shows anything.
2B 1  NATIVE Build - Calls to External API Call subsegment NOT traced   DOES NOT show in Xray graph

2b. Cloudwatch shows below error message:
2B 2  CloudWatch Logs - External API Call Subsegment discarded because of _X_AMZN_TRACE_ID is missing a trace ID, parent ID, or sampling decision7

@amitkumar7566 amitkumar7566 changed the title AWS Xray does not send tracing for Sub-segments in Native build Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build Jan 9, 2022
@amitkumar7566 amitkumar7566 changed the title Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build while using “controller”-based approach Jan 9, 2022
@amitkumar7566
Copy link
Author

amitkumar7566 commented Jan 10, 2022

@gsmet @radcortez

This class "com.amazonaws.xray.contexts.LambdaSegmentContext" seems to contain the missing information from where the below error arises and can be seen in Cloudwatch:
"_X_AMZN_TRACE_ID is missing a trace ID, parent ID, or sampling decision. Subsegment DynamoDB discarded."
"_X_AMZN_TRACE_ID is missing a trace ID, parent ID, or sampling decision. Subsegment External API Call discarded."

I also tried logging (AWS_REGION & _X_AMZN_TRACE_ID) two of the pre-defined AWS Lambda variables and below are the results:

A. In normal JVM build:

Both AWS_REGION & _X_AMZN_TRACE_ID values can be found in logs.

JVM Build - Env variables in logs

B. In Native build:

AWS_REGION value can be found in logs but _X_AMZN_TRACE_ID value logs as null.

Native Build - Env variables in logs

@radcortez
Copy link
Member

Thanks! I'll have a look.

@amitkumar7566
Copy link
Author

amitkumar7566 commented Jan 11, 2022

@radcortez
We are not setting it anywhere.. It should be automatically be pushed in AWS Lambda... However, it doesn't.
You can see the last screenshot. I tried to get it from Environment variable but it not available in native build.

The X-ray seems to work when we use lambda "handler" but does not work when we use "controller".

Anyways, you have the sample code.
Can you please test on this application by making the changes which you think should work?
I have shared the reproducer with you.

@radcortez
Copy link
Member

I did some additional digging, and most likely this is related to the following substitution:
https://github.com/quarkusio/quarkus/blob/main/extensions/amazon-lambda-xray/runtime/src/main/java/io/quarkus/amazon/lambda/xray/graal/LambdaSegmentContextSubstitution.java#L11

Probably this only surfaces in subsegments, because there is a direct call to LambdaSegmentContext to create the subsegment, which tries to read the traceId and for native mode with the substitution code, and in this case, the traceid is not available in the request.

@amitkumar7566 can you please provide me with more information about how are you deploying your Quarkus application? Thanks!

@patriot1burke
Copy link
Contributor

I think the issue is that the trace id is stored in a thread local. Resteasy requests are processed in a different thread from the native pull thread so the trace id is lost.

@amitkumar7566
Copy link
Author

@radcortez I am using AWS cloudformation to deploy. You can find the template in reproducer code.

@patriot1burke What is the solution for the issue that you have mentioned above?

@patriot1burke
Copy link
Contributor

patriot1burke commented Jan 19, 2022

@amitkumar7566 I don't a solution yet. Trying to figure out best way to do it.

@radcortez
Copy link
Member

@patriot1burke isn't the trace id thread-local storage used only for native mode? At least the only reference I can find is in LambdaSegmentContextSubstitution. And I guess the substitution was required because of aws/aws-xray-sdk-java#252.

If X-Ray, now allows the propagation using system properties, we can probably revert back to the original code and drop the thread-local plus substitution?

@patriot1burke
Copy link
Contributor

Native would only ever be able to process one request at a time though. Was eventually going to look at adding concurrent request processing and rewrite the poll loop to be non-blocking.

@patriot1burke
Copy link
Contributor

I'll revert it for now.

@patriot1burke
Copy link
Contributor

@radcortex @amitkumar7566 Please see linked PR if you want to verify this works.

@quarkus-bot quarkus-bot bot added this to the 2.8 - main milestone Jan 20, 2022
@patriot1burke
Copy link
Contributor

@amitkumar7566 Did you test tracing? Or did you just look at the output of your example program?

I'm pretty sure custom lambda runtime (binary lambdas) do not set the _X_AMZN_TRACE_ID environment variable. The system property com.amazonaws.xray.traceHeader is set by the quarkus lambda integration and should be picked up by xray library. Your example code prints out this env var, but not the system property.

FYI: Here's the code from the XRAY amazon library that obtains the trace id.

https://github.com/aws/aws-xray-sdk-java/blob/master/aws-xray-recorder-sdk-core/src/main/java/com/amazonaws/xray/contexts/LambdaSegmentContext.java#L46

Also, you can speed up the quarkus build by doing running:

mvn -DskipTests test-compile jar:test-jar install

@amitkumar7566
Copy link
Author

@patriot1burke I checked in AWS Xray but could not find any sub-segment traces.

image

However, I got the TraceId in logs when I pulled it from System property:

image

Also, we are getting below error in cloudwatch.

Full error logs below for DynamoDB call:


START RequestId: b782dba7-0548-46a1-b897-6b1e871aa972 Version: $LATEST
--
Lambda AWS Region: us-east-1
Lambda TraceId from Env Var: null
Lambda TraceId from Sys Prop: Root=1-61f0f21d-7088c7e9274883775a8bb13d;Parent=7742689ad0dc21bf;Sampled=1
DynamoDb Region: us-east-1
DynamoDb Endpoint: https://dynamodb.us-east-1.amazonaws.com
2022-01-26 07:02:53,582 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /books/db failed, error id: 4975858b-1c22-4ea0-8186-17468d77cc2f-2: org.jboss.resteasy.spi.UnhandledException: com.oracle.svm.core.jdk.UnsupportedFeatureError: Target_java_lang_ClassLoader.getClassLoadingLock(String)
at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:105)
at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:359)
at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:218)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:519)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:91)
at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:829)
at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:596)
at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
Caused by: com.oracle.svm.core.jdk.UnsupportedFeatureError: Target_java_lang_ClassLoader.getClassLoadingLock(String)
at com.oracle.svm.core.util.VMError.unsupportedFeature(VMError.java:87)
at java.lang.ClassLoader.getClassLoadingLock(ClassLoader.java:200)
at com.fasterxml.jackson.module.afterburner.util.MyClassLoader.loadAndResolve(MyClassLoader.java:79)
at com.fasterxml.jackson.module.afterburner.ser.PropertyAccessorCollector.generateAccessorClass(PropertyAccessorCollector.java:170)
at com.fasterxml.jackson.module.afterburner.ser.PropertyAccessorCollector.findAccessor(PropertyAccessorCollector.java:97)
at com.fasterxml.jackson.module.afterburner.ser.SerializerModifier.changeProperties(SerializerModifier.java:66)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.constructBeanOrAddOnSerializer(BeanSerializerFactory.java:414)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.findBeanOrAddOnSerializer(BeanSerializerFactory.java:294)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory._createSerializer2(BeanSerializerFactory.java:239)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.createSerializer(BeanSerializerFactory.java:173)
at com.fasterxml.jackson.databind.SerializerProvider._createUntypedSerializer(SerializerProvider.java:1495)
at com.fasterxml.jackson.databind.SerializerProvider._createAndCacheUntypedSerializer(SerializerProvider.java:1443)
at com.fasterxml.jackson.databind.SerializerProvider.findValueSerializer(SerializerProvider.java:544)
at com.fasterxml.jackson.databind.SerializerProvider.findTypedValueSerializer(SerializerProvider.java:822)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:308)
at com.fasterxml.jackson.databind.ObjectMapper.valueToTree(ObjectMapper.java:3389)
at com.amazonaws.xray.entities.SubsegmentImpl.getStreamSerializeObjectNode(SubsegmentImpl.java:141)
at com.amazonaws.xray.entities.SubsegmentImpl.streamSerialize(SubsegmentImpl.java:154)
at com.amazonaws.xray.emitters.UDPEmitter.sendSubsegment(UDPEmitter.java:104)
at com.amazonaws.xray.AWSXRayRecorder.endSubsegment(AWSXRayRecorder.java:582)
at com.amazonaws.xray.interceptors.TracingInterceptor.afterExecution(TracingInterceptor.java:288)
at software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain.lambda$afterExecution$11(ExecutionInterceptorChain.java:192)
at software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain.reverseForEach(ExecutionInterceptorChain.java:234)
at software.amazon.awssdk.core.interceptor.ExecutionInterceptorChain.afterExecution(ExecutionInterceptorChain.java:192)
at software.amazon.awssdk.core.internal.http.pipeline.stages.AfterExecutionInterceptorsStage.execute(AfterExecutionInterceptorsStage.java:26)
at software.amazon.awssdk.core.internal.http.pipeline.RequestPipelineBuilder$ComposingRequestPipelineStage.execute(RequestPipelineBuilder.java:206)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:37)
at software.amazon.awssdk.core.internal.http.pipeline.stages.ExecutionFailureExceptionReportingStage.execute(ExecutionFailureExceptionReportingStage.java:26)
at software.amazon.awssdk.core.internal.http.AmazonSyncHttpClient$RequestExecutionBuilderImpl.execute(AmazonSyncHttpClient.java:193)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.invoke(BaseSyncClientHandler.java:103)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.doExecute(BaseSyncClientHandler.java:167)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.lambda$execute$1(BaseSyncClientHandler.java:82)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.measureApiCallSuccess(BaseSyncClientHandler.java:175)
at software.amazon.awssdk.core.internal.handler.BaseSyncClientHandler.execute(BaseSyncClientHandler.java:76)
at software.amazon.awssdk.core.client.handler.SdkSyncClientHandler.execute(SdkSyncClientHandler.java:45)
at software.amazon.awssdk.awscore.client.handler.AwsSyncClientHandler.execute(AwsSyncClientHandler.java:56)
at software.amazon.awssdk.services.dynamodb.DefaultDynamoDbClient.scan(DefaultDynamoDbClient.java:4631)
at software.amazon.awssdk.services.dynamodb.paginators.ScanIterable$ScanResponseFetcher.nextPage(ScanIterable.java:134)
at software.amazon.awssdk.services.dynamodb.paginators.ScanIterable$ScanResponseFetcher.nextPage(ScanIterable.java:125)
at software.amazon.awssdk.core.pagination.sync.PaginatedResponsesIterator.next(PaginatedResponsesIterator.java:58)
at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable$ItemsIterator.<init>(PaginatedItemsIterable.java:58)
at software.amazon.awssdk.core.pagination.sync.PaginatedItemsIterable.iterator(PaginatedItemsIterable.java:48)
at java.lang.Iterable.spliterator(Iterable.java:101)
at software.amazon.awssdk.core.pagination.sync.SdkIterable.stream(SdkIterable.java:34)
at com.amitkumar.repository.XrayNativeImageTestRepository.findAll(XrayNativeImageTestRepository.java:25)
at com.amitkumar.repository.XrayNativeImageTestRepository_ClientProxy.findAll(Unknown Source)
at com.amitkumar.service.XrayNativeImageTestService.getBooks(XrayNativeImageTestService.java:21)
at com.amitkumar.service.XrayNativeImageTestService_ClientProxy.getBooks(Unknown Source)
at com.amitkumar.resource.XrayNativeImageTestResource.getBooksFromDb(XrayNativeImageTestResource.java:61)
at com.amitkumar.resource.XrayNativeImageTestResource_ClientProxy.getBooksFromDb(Unknown Source)
at java.lang.reflect.Method.invoke(Method.java:566)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
... 17 more
END RequestId: b782dba7-0548-46a1-b897-6b1e871aa972
REPORT RequestId: b782dba7-0548-46a1-b897-6b1e871aa972	Duration: 52.72 ms	Billed Duration: 53 ms	Memory Size: 1024 MB	Max Memory Used: 107 MB	XRAY TraceId: 1-61f0f21d-7088c7e9274883775a8bb13d	SegmentId: 45d0bb1c5b2955a9	Sampled: true

Full error logs below for REST Client call:

START RequestId: 75f87e27-2a38-4a1c-8a5e-bc798a0c2fee Version: $LATEST
--
__  ____  __  _____   ___  __ ____  ______
--/ __ \/ / / / _ \| / _ \/ //_/ / / / __/
-/ /_/ / /_/ / __ \|/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ \|_/_/\|_/_/\|_\|\____/___/
2022-01-26 07:01:06,660 INFO  [io.quarkus] (main) xray-native-image-test 1.0.0-SNAPSHOT native (powered by Quarkus 999-SNAPSHOT) started in 0.246s.
2022-01-26 07:01:06,661 INFO  [io.quarkus] (main) Profile prod activated.
2022-01-26 07:01:06,661 INFO  [io.quarkus] (main) Installed features: [amazon-dynamodb, amazon-lambda, cdi, rest-client, rest-client-jackson, resteasy, resteasy-jackson, security, smallrye-context-propagation, vertx]
2022-01-26 07:01:06,688 INFO  [com.ama.xra.con.DaemonConfiguration] (executor-thread-0) Environment variable AWS_XRAY_DAEMON_ADDRESS is set. Emitting to daemon on address 169.254.79.129:2000.
2022-01-26 07:01:06,688 INFO  [com.ama.xra.AWSXRayRecorder] (executor-thread-0) Overriding contextMissingStrategy. Environment variable AWS_XRAY_CONTEXT_MISSING has value: "LOG_ERROR".
2022-01-26 07:01:06,688 INFO  [com.ama.xra.con.DaemonConfiguration] (executor-thread-0) Environment variable AWS_XRAY_DAEMON_ADDRESS is set. Emitting to daemon on address 169.254.79.129:2000.
2022-01-26 07:01:06,842 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-0) HTTP Request to /books/restclient failed, error id: 4975858b-1c22-4ea0-8186-17468d77cc2f-1: org.jboss.resteasy.spi.UnhandledException: com.oracle.svm.core.jdk.UnsupportedFeatureError: Target_java_lang_ClassLoader.getClassLoadingLock(String)
at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:105)
at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:359)
at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:218)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:519)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:91)
at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:829)
at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:596)
at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
Caused by: com.oracle.svm.core.jdk.UnsupportedFeatureError: Target_java_lang_ClassLoader.getClassLoadingLock(String)
at com.oracle.svm.core.util.VMError.unsupportedFeature(VMError.java:87)
at java.lang.ClassLoader.getClassLoadingLock(ClassLoader.java:200)
at com.fasterxml.jackson.module.afterburner.util.MyClassLoader.loadAndResolve(MyClassLoader.java:79)
at com.fasterxml.jackson.module.afterburner.ser.PropertyAccessorCollector.generateAccessorClass(PropertyAccessorCollector.java:170)
at com.fasterxml.jackson.module.afterburner.ser.PropertyAccessorCollector.findAccessor(PropertyAccessorCollector.java:97)
at com.fasterxml.jackson.module.afterburner.ser.SerializerModifier.changeProperties(SerializerModifier.java:66)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.constructBeanOrAddOnSerializer(BeanSerializerFactory.java:414)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.findBeanOrAddOnSerializer(BeanSerializerFactory.java:294)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory._createSerializer2(BeanSerializerFactory.java:239)
at com.fasterxml.jackson.databind.ser.BeanSerializerFactory.createSerializer(BeanSerializerFactory.java:173)
at com.fasterxml.jackson.databind.SerializerProvider._createUntypedSerializer(SerializerProvider.java:1495)
at com.fasterxml.jackson.databind.SerializerProvider._createAndCacheUntypedSerializer(SerializerProvider.java:1443)
at com.fasterxml.jackson.databind.SerializerProvider.findValueSerializer(SerializerProvider.java:544)
at com.fasterxml.jackson.databind.SerializerProvider.findTypedValueSerializer(SerializerProvider.java:822)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:308)
at com.fasterxml.jackson.databind.ObjectMapper.valueToTree(ObjectMapper.java:3389)
at com.amazonaws.xray.entities.SubsegmentImpl.getStreamSerializeObjectNode(SubsegmentImpl.java:141)
at com.amazonaws.xray.entities.SubsegmentImpl.streamSerialize(SubsegmentImpl.java:154)
at com.amazonaws.xray.emitters.UDPEmitter.sendSubsegment(UDPEmitter.java:104)
at com.amazonaws.xray.contexts.LambdaSegmentContext.endSubsegment(LambdaSegmentContext.java:138)
at com.amazonaws.xray.AWSXRayRecorder.endSubsegment(AWSXRayRecorder.java:630)
at com.amazonaws.xray.AWSXRay.endSubsegment(AWSXRay.java:125)
at com.amitkumar.resource.XrayNativeImageTestResource.getBooksFromRestClient(XrayNativeImageTestResource.java:71)
at com.amitkumar.resource.XrayNativeImageTestResource_ClientProxy.getBooksFromRestClient(Unknown Source)
at java.lang.reflect.Method.invoke(Method.java:566)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
... 17 more
END RequestId: 75f87e27-2a38-4a1c-8a5e-bc798a0c2fee
REPORT RequestId: 75f87e27-2a38-4a1c-8a5e-bc798a0c2fee	Duration: 177.25 ms	Billed Duration: 578 ms	Memory Size: 1024 MB	Max Memory Used: 101 MB	Init Duration: 400.72 ms	XRAY TraceId: 1-61f0f1b1-364383e93515c4734f73bf43	SegmentId: 74ed1c5d1e09f416	Sampled: true

@gsmet gsmet removed this from the 2.7.0.Final milestone Jan 26, 2022
@patriot1burke
Copy link
Contributor

Have to exclude th jackson-module-afterburner artifact. Let me look into how to do that.

@patriot1burke
Copy link
Contributor

patriot1burke commented Jan 26, 2022

So, let me explain what's happening. Afterburner is an addon for json serialization that an aws library transitive dependency is using. It creates classes dynamically at runtime. You cannot do this with Graal/native binaries. What I think will work is to exclude the afterburner module. Change this:

<dependency>
      <groupId>io.quarkus</groupId>
      <artifactId>quarkus-amazon-lambda-rest</artifactId>
</dependency>

to this:

<dependency>
      <groupId>io.quarkus</groupId>
      <artifactId>quarkus-amazon-lambda-rest</artifactId>
      <exclusions>
                <exclusion>
                    <groupId>com.fasterxml.jackson.module</groupId>
                    <artifactId>jackson-module-afterburner</artifactId>
                </exclusion>
        </exclusions>
</dependency>

@amitkumar7566
Copy link
Author

@patriot1burke When I excluded Afterburner like mentioned above, here is what I get as error:

image

@patriot1burke
Copy link
Contributor

Excluding afterburner won't work (obviously :) ) I have another incoming PR that will hopefully fix the problem.

The issue is that quarkus-amazon-rest depends on aws-serverless artifact. There is a static block that registers afterburner and code substitutions don't run until after static initialization (static initialization happens at build time with our Graal integration). I'm removing the aws-serverless library dependency and that should solve the problem.

@patriot1burke
Copy link
Contributor

Ok, merge is in, try it now (you don't need the excludes anymore FYI).

@amitkumar7566
Copy link
Author

@patriot1burke I tried as instructed above.. No luck !!

@patriot1burke
Copy link
Contributor

Same error?

@amitkumar7566
Copy link
Author

@patriot1burke No error at build time...
There is not X-ray trace.. Not sure if quarkus-amazon-lambda-rest dependency is functioning correctly or not in the snapshot.

@patriot1burke
Copy link
Contributor

@amitkumar7566 I was able to see an xray trace using latest quarkus and with a native binary build. Here's the project I used:

https://github.com/patriot1burke/xray-demo

README has details.

I did see the subsegment I created within a trace call within the AWS console.

@amitkumar7566
Copy link
Author

@patriot1burke
Here is the difference between your sample and mine:

  1. You have used "quarkus-amazon-lambda-http" dependency which is for the AWS HTTP API feature of AWS API Gateway. We use "quarkus-amazon-lambda-rest dependency " which is for the AWS REST API feature of AWS API Gateway.
  2. The Xray should pick and send the sub-segment traces while "quarkus-amazon-lambda-rest" dependency is used. And it is not the case here.

Also please find below some analysis:

  1. To trace the sub-segments of any of the AWS services like DynamoDB, Secrets Manager, SSM, etc (which are probably 200 or above now), we don't need to write a single line of code.
    By adding the below dependency, it should automatically instrument and trace sub-segments of all the AWS services used in the application code and send it to AWS Xray.
    It happens in JVM build but not in Native build (We can see both sub-segment as well as in Xray graph).
<dependency>
      <groupId>com.amazonaws</groupId>
      <artifactId>aws-xray-recorder-sdk-aws-sdk-v2-instrumentor</artifactId>
      <version>version number</version>
</dependency>
  1. To trace the sub-segments of any of the Custom code in the application, we need to surround the code block like below.
    It happens in JVM build but not in Native build (We can see the sub-segment but nothing in the Xray graph).
Subsegment subsegment = AWSXRay.beginSubsegment("External API Call");
   // Your codes for which sub-segment traces are required.
   // This serves the purpose for tracing the time taken by any external API call too.
AWSXRay.endSubsegment();

Hope this helps you with some clarification.

@patriot1burke
Copy link
Contributor

@amitkumar7566 That helps a lot and narrows down the problem.

quarkus-amazon-lambda-http vs. quarkus-amazon-lambda-rest wouldn't make a difference.
Trace id is propagated in a common layer to both of those extensions.

So it looks like the instrumentor isn't working in native. I worry that the instrumentor requires the JVM and won't work in native. Depends if its a compile or runtime thing. I'll look into how XRAY works more.

@patriot1burke
Copy link
Contributor

@amitkumar7566 I updated my example to use quarkus-amazon-lambda-rest and I'm still able to see the subsegment in the trace

image

I'll look into getting your example to work.

@patriot1burke
Copy link
Contributor

@amitkumar7566 I was able to get your example to work with latest Quarkus "main" branch build. No new fixes. I executed both the /books/db and /books/restclient endpoints. Here's a screen shot:

image

and

image

@patriot1burke
Copy link
Contributor

@amitkumar7566 Here's the pom. I made some minor changes to point to 999-SNAPSHOT.

https://gist.github.com/patriot1burke/5c89ca20b04eae87269845cd540967cd

@amitkumar7566
Copy link
Author

@patriot1burke I validated and now I can see sub-segments for both AWS Services (DynamoDB) & External API Call.

1. DynamoDB
DynamoDB

  1. External API Call
    External API Call

As this test has been done on 999-SNAPSHOT, below are our questions/concerns:

  1. In which next version/release will this patch/feature be available for public use by default?
  2. In case it is released in your next version (which will be anyone after 2.7.0 as it is already live), how can this defect be fixed in the quarkus versions of 2.0.x & 2.3.x?

Our APIs which had gone to production last year use 2.0.x & 2.3.x and the ones being developed currently does not have this defect fix too.
We are eager to know your plan on the above 2 questions.

@patriot1burke
Copy link
Contributor

You are using unsupported community versions and not using our product bits. From our product manager: "What needs to be discussed with the customer is what version they should use. The customer is using unsupported extensions in an unsupported configuration so to me it probably makes the most sense that the customer updates to the latest community 2.7.1. The fix will then be added to RHBQ 2.7 when it arrives (planned for April)."

@geoand
Copy link
Contributor

geoand commented Feb 7, 2022

@patriot1burke so can this issue be closed?

From what I understand, the fix has already landed, correct?

@geoand geoand added triage/out-of-date This issue/PR is no longer valid or relevant and removed triage/needs-reproducer We are waiting for a reproducer. labels Feb 7, 2022
@patriot1burke
Copy link
Contributor

@amitkumar7566 This patch to our xray extension is already within community release 2.7.0.Final. I strongly suggest you upgrade your production systems to either the Red Hat supported bits of Quarkus or to the latest community version of quarkus.

@paulrobinson
Copy link
Contributor

Thanks Bill.

@amitkumar7566: We don't have a Red Hat supported version of Quarkus 2.7.0.Final released yet. But upgrading to community Quarkus 2.7.0.Final would put you in the best position ready for when the Red Hat Build of Quarkus 2.7 product is released.

@amitkumar7566
Copy link
Author

@patriot1burke @paulrobinson
I can see that Quarkus released 2.7.1.Final yesterday.
Is this X-Ray fix available in 2.7.1.Final too ?

@geoand
Copy link
Contributor

geoand commented Feb 9, 2022

Yes, the fix is available since 2.7.0.Final

@amitkumar7566 amitkumar7566 changed the title Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build while using “controller”-based approach Quarkus doesn’t send X-Ray traces to AWS for sub-segments in Native build while using RESTEasy “controller” based approach Feb 9, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/smallrye area/tracing kind/bug Something isn't working triage/out-of-date This issue/PR is no longer valid or relevant
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants