Quarkus: --initialize-at-build-time appears to be ignored | AWS XRay SDK

[sherl0cks]

Describe the bug
I'm trying to get the AWS XRay SDK working using Manual Instrumentation from this doc. When doing so, I get an error during mvn clean install -Dnative -Dquarkus.native.container-build=true :

Caused by: com.oracle.graal.pointsto.constraints.UnsupportedFeatureException: Detected a FileDescriptor in the image heap. File descriptors opened during image generation are no longer open at image run time, and the files might not even be present anymore at image run time.  To see how this object got instantiated use -H:+TraceClassInitialization. The object was probably created by a class initializer and is reachable from a static field. You can request class initialization at image run time by using the option --initialize-at-build-time=<class-name>. Or you can write your own initialization methods and call them explicitly from your main entry point.
Detailed message:
Trace:  object java.net.PlainDatagramSocketImpl
        object java.net.DatagramSocket
        object com.amazonaws.xray.emitters.DefaultEmitter
        object com.amazonaws.xray.AWSXRayRecorder
        field com.amazonaws.xray.AWSXRay.globalRecorder

Setting --initialize-at-build-time=com.amazonaws.xray in quarkus.native.additional-build-args appears to have no effect. I notice that --initialize-at-build-time= is set twice per #5480.

Expected behavior
Setting --initialize-at-build-time=com.amazonaws.xray would lead the static field with a file handle to resolve at build time, and the stack trace to go away.

Actual behavior
It doesn't happen, even though I'm following guidance from the stacktrace.

To Reproduce
Steps to reproduce the behavior:

1. Add to your pom.xml

        <dependency>
            <groupId>com.amazonaws</groupId>
            <artifactId>aws-xray-recorder-sdk-aws-sdk-v2</artifactId>
            <version>2.4.0</version>
        </dependency>

1. Instrument the AWS SDK per Manual Instrumentation from this doc.
2. Update application.properties with --initialize-at-build-time=com.amazonaws.xray
3. mvn clean install -Dnative -Dquarkus.native.container-build=true

Configuration

quarkus.lambda.handler=myHandler
quarkus.ssl.native=true
quarkus.native.additional-build-args=\
  -H:ReflectionConfigurationFiles=reflection-config.json,\
  --initialize-at-build-time=com.amazonaws.xray,\
  --initialize-at-run-time=com.some.avro

Environment (please complete the following information):

• Output of uname -a or ver: Darwin Kernel Version 18.7.0: Sun Dec 1 18:59:03 PST 2019; root:xnu-4903.278.19~1/RELEASE_X86_64 x86_64
• Output of java -version: openjdk version "1.8.0_212"
  OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_212-b03)
  OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.212-b03, mixed mode)
• GraalVM version (if different from Java): 19.2.1-grl via sdkman
• Quarkus version or git rev: 1.1.1.Final

Additional context
If you need a reproducer, let me know. I could create one on Monday.

[gsmet]

By default, Quarkus initializes everything at build time and only selected classes at runtime.

The issue you have is because com.amazonaws.xray.emitters.DefaultEmitter is initialized at build time during the native image compilation and you end up with a file descriptor in the heap when the memory snapshot is taken.

What you want is to initialize this one at runtime.

[jaikiran]

Hello @sherl0cks,
I can understand why you used the --initialize-at-build-time - the error message says this:

You can request class initialization at image run time by using the option --initialize-at-build-time=<class-name>

Unfortunately, that error message (from Graal) has a typo. It should have said --initialize-at-run-time. That error message has been fixed upstream in Graal https://github.com/oracle/graal/pull/1854. I don't know if it made 19.3.x release of Graal or whether it will only be in 20.x release of Graal.

[sherl0cks]

@jaikiran @gsmet Thanks, this is useful info. When I switch the package to initialize at runtime, I get the below. I cannot seem to find any docs on the subject. How do I handle this?

2020-01-25 01:21:50,234 SEVERE [com.ama.xra.int.TracingInterceptor] (Lambda Thread) Unable to parse default operation parameter whitelist at file:/project/lib/com.amazonaws.aws-xray-recorder-sdk-aws-sdk-v2-2.4.0.jar!/com/amazonaws/xray/interceptors/DefaultOperationParameterWhitelist.json. This will affect this handler's ability to capture AWS operation parameter information.: java.nio.file.NoSuchFileException: /project/lib/com.amazonaws.aws-xray-recorder-sdk-aws-sdk-v2-2.4.0.jar

[sherl0cks]

OK - looks like I can resolve the file by changing the --initialize-at-run-time=com.amazonaws.xray.AWSXray to the whole package --initialize-at-run-time=com.amazonaws.xray. This gets past the first issue, but now I have a commons logging issue. The solution discussed to exclude the transitives in https://quarkus.io/guides/dynamodb#configuring-dynamodb-clients does not seem to work. Thoughts?

I know #4968 is tackling a bigger AWS refactor. I haven't been able to check if xray was in there yet. If not, it prob should be.

Caused by: org.apache.commons.logging.LogConfigurationException: java.lang.ClassNotFoundException: org.apache.commons.logging.impl.LogFactoryImpl (Caused by java.lang.ClassNotFoundException: org.apache.commons.logging.impl.LogFactoryImpl)
    at org.apache.commons.logging.LogFactory.createFactory(LogFactory.java:1158)
    at org.apache.commons.logging.LogFactory$2.run(LogFactory.java:960)
    at java.security.AccessController.doPrivileged(AccessController.java:69)
    at org.apache.commons.logging.LogFactory.newFactory(LogFactory.java:957)
    at org.apache.commons.logging.LogFactory.getFactory(LogFactory.java:624)
    at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:655)
    at com.amazonaws.xray.interceptors.TracingInterceptor.<clinit>(TracingInterceptor.java:42)
    at com.oracle.svm.core.hub.ClassInitializationInfo.invokeClassInitializer(ClassInitializationInfo.java:350)
    at com.oracle.svm.core.hub.ClassInitializationInfo.initialize(ClassInitializationInfo.java:270)
    ... 24 more
Caused by: java.lang.ClassNotFoundException: org.apache.commons.logging.impl.LogFactoryImpl
    at com.oracle.svm.core.hub.ClassForNameSupport.forName(ClassForNameSupport.java:60)
    at java.lang.ClassLoader.loadClass(Target_java_lang_ClassLoader.java:131)
    at org.apache.commons.logging.LogFactory.createFactory(LogFactory.java:1020)
    ... 32 more

[gsmet]

Just exclude commons-logging and use https://search.maven.org/artifact/org.jboss.logging/commons-logging-jboss-logging/1.0.0.Final/jar instead.

[sherl0cks]

Got passed the logging libs issues by adding the logging artifact as top level dep and excluding commons logging from ALL aws deps. Now working to resolve registering for reflecting items around Jackson

@gsmet any feedback if https://github.com/quarkusio/quarkus/pull/4968 will seek to address AWS X Ray? If not, we may be interested to publish an xray extension, cuz getting this bootstrapped is a pain.

[sherl0cks]

Got reflection working, and we've run into what appears to be a more fundamental issue. At runtime, everything boots up correctly, but when tracing should begin, we get the following:
WARN [com.ama.xra.con.LambdaSegmentContext] (Lambda Thread) _X_AMZN_TRACE_ID is missing a trace ID, parent ID, or sampling decision. Subsegment S3 discarded.

It appears the root cause here is that AWS Lambda Custom Runtimes are required to do several things, including propagate the _X_AMZN_TRACE_ID environment variable. The quarkus lambda extension handles these concerns in Java code, but does not handle pass on _X_AMZN_TRACE_ID from the /runtime/invocation/next invocation. Digging into the AWS XRay SDK, there does not appear to be a way to set the trace id in the recorder apart from a environment variable though I haven't looked at this extensively.

So at this point, it appears that sending xray subsegments is not possible with the current aws lambda extension for quarkus, and that we have the following options forward:

1. update the quarkus extension with some approach to set the env var despite the fact that java doesn't allow that by default.
2. change the strategy for the quarkus lambda extension to use a bootstrap script to set the env vars and then pass information to the quarkus process
3. ask if aws will allow another way of setting the trace ID, perhaps via a system property?

[sherl0cks]

@patriot1burke ☝️ given you wrote most of that lambda extension that handles these concerns and may have some thoughts on this.

[sherl0cks]

Bumping this thread @gsmet @patriot1burke @jaikiran. This is a must have feature for any one that wants to deploy quarkus to production on AWS Lambda, which is precisely what we want to do. We are interested and willing to contribute a PR here, but we’d like agreement on a general direction before doing so.

[patriot1burke]

I should be able to look at it on Tuesday. Looks like a simple fix.

[sherl0cks]

Great news. Let us know if you need any input / testing / etc.

[patriot1burke]

• Propagate the tracing header – Get the X-Ray tracing header from the Lambda-Runtime-Trace-Id header in the API response. Set the _X_AMZN_TRACE_ID environment variable with the same value for the X-Ray SDK to use.

@sherl0cks X-RAY recorder (java) looks for the env var? Looks like you can hack env variables within java: https://stackoverflow.com/questions/318239/how-do-i-set-environment-variables-from-java

@gsmet I think we need a AWS X-Ray extension that:

• Sets the --initialize-at-run-time flag
• excludes apache logging

I can code this up quickly. Testing it is another matter as I'm completely unfamiliar with xray

[sherl0cks]

@patriot1burke I’m not an JAVA AWS xray SDK expert, but fortunately the source is oss , and from my reading of the code and docs, there is no other way to set the variable in the SDK than the environment variable. Link to code on github in one of my comments above.

I’m fine with whatever approach y’all want to maintain. Random thought - does process builder have platform specific code which may cause issues with native executables?

We can test this with X-ray in AWS Lambda so long as we have guidance on how to build/consume the appropriate dependency.

[patriot1burke]

@sherl0cks See my stackoverflow link above. I think getenv is hackable. Can only try it :)

[patriot1burke]

I just don't want to have to wrap this in a bootstrap shell script. Would be a big performance hit.

[patriot1burke]

Sorry for the extra comment, but @sherl0cks scroll down on that stackoverflow link. Somebody shows how to hack getenv.

[sherl0cks]

Ah ok. Let us know how/when to test.

[patriot1burke]

@sherl0cks XRAY kinda sucks for depending on an environment variable. Especially a value that is per-request dependent. This means that if you are using xray, you can't process multiple requests at once which is something we wanted to do.

FYI: @n1hility @stuartwdouglas

[sherl0cks]

@patriot1burke perhaps worth a discussion with AWS folks? The Lambda custom runtime docs are pretty clear about these steps. That said, the NodeJS runtime provided by AWS has support for several promises runtime at once, so my guess is that somehow the nodejs XRAY SDK must be aware?

I can open an issue over there in the AWS repo if you would like to discuss. These sorts of design concerns are exactly why I was pushing on this issue - these are pretty fundamental choices.

[patriot1burke]

@sherl0cks Actually instead of hacking System.getenv, which may or may not work, I think I'll just code replace LambdaSegmentContext.getTraceHeaderFromEnvironment

[patriot1burke]

@sherl0cks Ok, I have a branch you can try out. I don't know if the xray bytecode subsitution works yet as I need to set up an xray example and don't know how to do it. Its probably gonna be at least a day before I have time to look into XRAY to fully test this out.

YOU DO NOT NEED TO:

• You will not have to Include the xray maven dependency in your build. This will be included by an extension
• You will not have to set the --initialize-at-runtime flag
• You will not have to exclude commons-logging

What you Need to do:

$ git clone [email protected]:patriot1burke/quarkus.git
$ get checkout lambda-trace
$ cd quarkus
$ mvn -DskipTests -Dmaven.test.skip=true clean install

You will then need to

• Change your quarkus version to "999-SNAPSHOT"
• add the quarkus-amazon-lambda-xray dependency to your quarkus project.

Here is an example

What did I do?

• I changed the amazon-lambda extension to store the trace id header in a class called TraceId in a ThreadLocal variable
• The quarkus-amazon-lambda-xray extension does a bytecode substitution to pull that ThreadLocal variable See here
• The xray extension also excludes commons-logging and also adds the --initialize-at-runtime flag.

If you do a diff from master you should see that I added very little code. if what I did doesn't work, you might be able to tweak it from there if this doesn't work.

[sherl0cks]

@patriot1burke thank you very much, we're looking into it now. Would you like us to help set up a reproducer for you?

[patriot1burke]

@sherl0cks That would be great. Most of the work though is weeding through all the config and console bits.

[christianThor]

@patriot1burke I'm on @sherl0cks's team, just tested the change and can confirm it's working!

I can help get the reproducer set up so we can show the configuration we used to get xray working seamlessly. There were several classes that needed to be registered in reflection-config.json and some proxy classes needed to be registered under this option -H:DynamicProxyConfigurationFiles

Thank you!

[patriot1burke]

@christianThor Yes, please make a list of the refection and proxies that are needed and we can make sure its automatically done.

[christianThor]

@patriot1burke here's the reproducer which should work if you try deploying the stack to AWS cloud defined by appTemplate.yml. I have not tried testing it using SAM local. I included an S3 client because our use case is coupled to the AWS SDK client, so there will be additional configuration necessary in the pom to get S3 client working. Hope this is helpful! Let us know if you need anymore info and help!

https://github.com/christianThor/quarkus-lambda-xray-reproducer

[sherl0cks]

@patriot1burke anything else we can do at this time to help you move this issue forward?

[sherl0cks]

@patriot1burke circling back to this, as this is an important issue for us and I'm hoping we can keep it moving forward. Anything we can do to help? Thoughts on what is needed to get this submitted upstream?

[patriot1burke]

I should be able to get back to this on Monday or Tuesday, with a PR by end of week.

[patriot1burke]

I can't promise anything after the PR though. Depends on when somebody is available to review and when master is released.

[sherl0cks]

@patriot1burke sounds good, we appreciate all your help so far. Do let us know if there is anything we can do to help out.

[patriot1burke]

@sherl0cks @christianThor I improved things a bit so there's less boilerplate to do. Here's what the config would look like.

quarkus.lambda.handler=test
quarkus.ssl.native=true
quarkus.native.additional-build-args=-H:DynamicProxyConfigurationFiles=dynamic-proxy-config.json

Eventually I want to be able to get rid of the wrapper shell script, and the need to package the lib.so file and cacert file, but not sure I'll be able to do that with the first PR.

You tell me, but, I also don't think the DynamicProxyConfig is related to Xray, and is more of a function of using apache. Need to think about how to remove that boilerplate too.

[christianThor]

Awesome! Yeah - it looks like it is connected to apache. Thank you @patriot1burke !

[patriot1burke]

FYI, submitted a PR for this.