Agent omitted one reflection: javax.xml.stream.FactoryConfigurationError: Provider com.sun.xml.internal.stream.XMLInputFactoryImpl not found

[kwojcik-blockether]

Story
I introduced a new feature in my framework which allows to generate all configuration files using
native-graalvm-agent. It works quite nice and I removed the majority of errors, but still I cannot
find a way to remove error provided below.

GraalVM version used:
graalvm-ce:19.0.2

Error message:

Exception in thread "main" javax.xml.stream.FactoryConfigurationError: Provider com.sun.xml.internal.stream.XMLInputFactoryImpl not found
	at javax.xml.stream.FactoryFinder.newInstance(FactoryFinder.java:201)
	at javax.xml.stream.FactoryFinder.newInstance(FactoryFinder.java:152)
	at javax.xml.stream.FactoryFinder.find(FactoryFinder.java:329)
	at javax.xml.stream.FactoryFinder.find(FactoryFinder.java:227)
	at javax.xml.stream.XMLInputFactory.newInstance(XMLInputFactory.java:154)
	at com.amazonaws.util.XmlUtils.createXmlInputFactory(XmlUtils.java:63)
	at com.amazonaws.util.XmlUtils.access$000(XmlUtils.java:27)
	at com.amazonaws.util.XmlUtils$1.initialValue(XmlUtils.java:36)
	at com.amazonaws.util.XmlUtils$1.initialValue(XmlUtils.java:33)
	at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:180)
	at java.lang.ThreadLocal.get(ThreadLocal.java:170)
	at com.amazonaws.util.XmlUtils.getXmlInputFactory(XmlUtils.java:54)
	at com.amazonaws.http.StaxResponseHandler.handle(StaxResponseHandler.java:94)
	at com.amazonaws.http.StaxResponseHandler.handle(StaxResponseHandler.java:42)
	at com.amazonaws.http.response.AwsResponseHandlerAdapter.handle(AwsResponseHandlerAdapter.java:70)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.handleResponse(AmazonHttpClient.java:1627)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeOneRequest(AmazonHttpClient.java:1336)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeHelper(AmazonHttpClient.java:1113)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.doExecute(AmazonHttpClient.java:770)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.executeWithTimer(AmazonHttpClient.java:744)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.execute(AmazonHttpClient.java:726)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutor.access$500(AmazonHttpClient.java:686)
	at com.amazonaws.http.AmazonHttpClient$RequestExecutionBuilderImpl.execute(AmazonHttpClient.java:668)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:532)
	at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:512)
	at com.amazonaws.services.sqs.AmazonSQSClient.doInvoke(AmazonSQSClient.java:2235)
	at com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:2202)
	at com.amazonaws.services.sqs.AmazonSQSClient.invoke(AmazonSQSClient.java:2191)
	at com.amazonaws.services.sqs.AmazonSQSClient.executeSendMessage(AmazonSQSClient.java:1758)
	at com.amazonaws.services.sqs.AmazonSQSClient.sendMessage(AmazonSQSClient.java:1730)
	at sqs_example.core$LOCAL_NEVER_CALL_DIRECTLY_ReceiveStringLambda__handleRequest$fn__177.invoke(core.clj:13)
	at sqs_example.core$LOCAL_NEVER_CALL_DIRECTLY_ReceiveStringLambda__handleRequest.invokeStatic(core.clj:9)
	at sqs_example.core$LOCAL_NEVER_CALL_DIRECTLY_ReceiveStringLambda__handleRequest.invoke(core.clj:9)
	at clojure.lang.AFn.applyToHelper(AFn.java:156)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at clojure.lang.Var.applyTo(Var.java:705)
	at clojure.core$apply.invokeStatic(core.clj:665)
	at clojure.core$apply.invoke(core.clj:660)
	at fierycod.holy_lambda.impl.util$call.invokeStatic(util.clj:54)
	at fierycod.holy_lambda.impl.util$call.doInvoke(util.clj:45)
	at clojure.lang.RestFn.invoke(RestFn.java:439)
	at clojure.core$partial$fn__5839.invoke(core.clj:2625)
	at fierycod.holy_lambda.core$process_event.invokeStatic(core.clj:222)
	at fierycod.holy_lambda.core$process_event.invoke(core.clj:217)
	at fierycod.holy_lambda.core$next_iter.invokeStatic(core.clj:238)
	at fierycod.holy_lambda.core$next_iter.invoke(core.clj:226)
	at clojure.lang.Var.invoke(Var.java:388)
	at sqs_example.core$_main.invokeStatic(core.clj:26)
	at sqs_example.core$_main.invoke(core.clj:26)
	at clojure.lang.AFn.applyToHelper(AFn.java:152)
	at clojure.lang.AFn.applyTo(AFn.java:144)
	at sqs_example.core.main(Unknown Source)
Caused by: java.lang.ClassNotFoundException: com.sun.xml.internal.stream.XMLInputFactoryImpl
	at com.oracle.svm.core.hub.ClassForNameSupport.forName(ClassForNameSupport.java:51)
	at java.lang.Class.forName(DynamicHub.java:1143)
	at javax.xml.stream.FactoryFinder.getProviderClass(FactoryFinder.java:125)
	at javax.xml.stream.FactoryFinder.newInstance(FactoryFinder.java:189)
	... 51 more

How to reproduce? (you will need: aws-cli, aws-sam, leiningen)

1. Clone the repository and checkout

git clone git@github.com:FieryCod/holy-lambda.git && git checkout bug/javax-xml-stream && cd holy-lambda

2. Build the graalvm image and install fnative util:

make build-docker install-fnative

3. Go to sqs-example and run

cd examples/sqs-example && make install-holy-lambda compile native-compile native-sqs-invoke

I think that the error might be connected with the warnings I receive from native-graalvm-agent:

WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}
WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}
WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}
WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}
WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}
WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}

Steps to reproduce the warnings:

1. Go to sqs-example

cd examples/sqs-example

2. Create a new SQS using Amazon UI
3. On line 12 at src/sqs_example/core.clj put your url to sqs
4. Create resources/envs.list file and populate the configuration

AWS_ACCESS_KEY=PUT_YOUR_ACCESS_KEY_HERE
AWS_SECRET_KEY=PUT_YOUR_SECRET_KEY_HERE

5. Compile and run

make install-holy-lambda compile gen-native-configuration

[SergejIsbrecht]

Are you sure you covered all relevant code paths with the agent? It seems a piece of code tries to load XMLInputFactoryImpl via Class#forName and XMLInputFactoryImpl is not in the native-image.

Caused by: java.lang.ClassNotFoundException: com.sun.xml.internal.stream.XMLInputFactoryImpl
	at com.oracle.svm.core.hub.ClassForNameSupport.forName(ClassForNameSupport.java:51)
	at java.lang.Class.forName(DynamicHub.java:1143)
	at javax.xml.stream.FactoryFinder.getProviderClass(FactoryFinder.java:125)

Could you please have a look whether XMLInputFactoryImpl is in the json reflection configuration file? If not, try to add it manually and try again.

The mentioned Exception does not look like it is related to XMLInputFactoryImpl. It seems that there is an error processing ClassUtil, when getEnclosingMethod is invoked.

WARNING: Error processing trace entry: java.lang.NullPointerException: {caller_class=com.fasterxml.jackson.databind.util.ClassUtil, result=null, args=[], function=getEnclosingMethod, tracer=reflect}

[kwojcik-blockether]

@SergejIsbrecht I'm certain that I covered all code paths with the agent.

My tool takes all the methods declared in -main method, then calls them with the payloads found in native-agents-payloads. Therefore ReceiveStringLambda method is called in the same way as the production one lambda.

After I added the following configuration the code started to working:

{
  "name":"com.sun.xml.internal.stream.XMLInputFactoryImpl",
  "methods":[{"name":"<init>","parameterTypes":[] }]
}

It seems to me that it's then more an issue in agent itself not in native-image.

[SergejIsbrecht]

I am also sure that the native image does what it is supposed to do. When there is no entry in the configuration file the class will not be included in the native image. Therefore you get a ClassNotFoundException during runtime. Could you generate a trace file when using the native agent? I will have a look at the src code of the agent and the class javax.xml.stream.FactoryFinder.getProviderClass(FactoryFinder.java:125), if source is available.

Maybe the agent does not trace a certain method, which is used for reflection. But there would probably an open issue already.

[SergejIsbrecht]

So I did some digging. This is the call, which will be done:

return Class.forName(className, false, FactoryFinder.class.getClassLoader());

I did some testing with GraalVM R19 JVM with the agent, which calls simular code:

public class Test123 {

  public static final String packageName = "de.sergej.";

  public static void main(String[] args) {
    Class<?> aClass = null;
    try {
      aClass = Class.forName(packageName + "Main");
    } catch (Exception ex) {
      throw new RuntimeException(ex);
    }

    X x = new X();

    Class<?> reflect = x.reflect(packageName + "Main2");

    System.out.println(aClass.toString());
    System.out.println(reflect.toString());
  }

  static class X {
    Class<?> reflect(String className) {
      try {
        return Class.forName(className, false, this.getClass().getClassLoader());
      } catch (ClassNotFoundException e) {
        throw new RuntimeException(e);
      }
    }
  }
}

Execution:
java -agentlib:native-image-agent=trace-output=/home/sergej/Development/Development/kotlinPlayground/build/classes/java/main/trace.json -cp . de.sergej.Test123

This will in turn generate following trace file:

{"caller_class":"de.sergej.Test123", "result":true, "args":["de.sergej.Main"], "function":"forName", "tracer":"reflect", "class":"java.lang.Class"},
{"caller_class":"sun.nio.fs.DefaultFileSystemProvider", "result":true, "args":["sun.nio.fs.LinuxFileSystemProvider"], "function":"forName", "tracer":"reflect", "class":"java.lang.Class"},
{"caller_class":"sun.nio.fs.DefaultFileSystemProvider", "result":true, "args":[], "function":"newInstance", "tracer":"reflect", "class":"sun.nio.fs.LinuxFileSystemProvider"},
{"caller_class":"de.sergej.Test123$X", "result":true, "args":["de.sergej.Main2"], "function":"forName", "tracer":"reflect", "class":"java.lang.Class"},

It seems to work for Class#forName(LString;) and Class#forName(LString;ZLClassLoader). Maybe try to re-run with the GraalVM JVM with the agent and the trace being active, just like I did in the Execution example.

[kwojcik-blockether]

@SergejIsbrecht After adding both failing and passing payload to agent the configuration produced by agent is valid. Thank you @SergejIsbrecht for you investigation.
Closing the issue.

[kwojcik-blockether]

@cstancu @SergejIsbrecht I've forgotten to remove the following snippet from reflect-config.json, before retesting.

{
  "name":"com.sun.xml.internal.stream.XMLInputFactoryImpl",
  "methods":[{"name":"<init>","parameterTypes":[] }]
}

Since the issue still exists I've reopened it. Here you can find a zipped trace.json file.
As you can see the following line is included in trace.json.

{"caller_class":"javax.xml.stream.FactoryFinder", "result":true, "args":["com.sun.xml.internal.stream.XMLInputFactoryImpl"], "function":"forName", "tracer":"reflect", "class":"java.lang.Class"}

For some reason there are no corresponding reflection config for com.sun.xml.internal.stream.XMLInputFactoryImpl in reflect-config.json.

EDIT
When I used the following command:

native-image-configure generate --trace-input=trace.json --output-dir=trace-configuration

I did not find any line regarding the com.sun.xml.internal.stream.XMLInputFactoryImpl

[peter-hofer]

Thank you for your report @FieryCod , and for your help @SergejIsbrecht . The case here is that the agent as well as native-image-configure filter reflection usage originating in the javax package (among others) under the assumption that native-image already ensures that such JDK code works out of the box. Evidently this is not the case for the javax.xml code, so I believe this is best solved by adding such support rather than having users specify its internal classes in a reflection configuration (even when it is automated via the agent). I'll prepare a patch and also look into those warnings.

[kwojcik-blockether]

@peter-hofer @SergejIsbrecht Thank you gentlemen. Could you please notify me when you'll finish the patch?