Quarkus: ClassNotFoundException: org.apache.commons.logging.impl.LogFactoryImpl

[sorin-costea]

Describe the bug
The native lambda crashes with the above message.

Expected behavior
No crash :)

Actual behavior
The "official" suggestion to add commons-logging-jboss-logging doesn't help as that package doesn't provide LogFactoryImpl and the alternative usage of reflection.json seems a REAL overkill... :(

To Reproduce
Both org.elasticsearch.client:elasticsearch-rest-high-level-client and software.amazon.awssdk:apache-client depend on commons-logging but somehow when I build the native image this is missing. Even after adding commons-logging to the pom, the error is the same.

Environment (please complete the following information):

• AWS Lambda, custom runtime V2
• Mandrel 20.3-java11
• Maven

[quarkus-bot[bot]]

/cc @galderz, @gsmet, @loicmathieu, @yrodiere, @zakkak

[sorin-costea]

PS: I need the software.amazon.awssdk:apache-client because the AWS SSM client is not "quarkified" (yet?) and can't find a HttpClient otherwise. But even without this, the Elasticsearch client will use commons-logging...

PPS: the project works fine as a JAR deployed in Java11 Lambda runtime. Just the native not.

[gsmet]

Could we have the full stack trace? Also a reproducer would be useful. It doesn't need to be a lambda if what you suspect is true.

[sorin-costea]

Reproducer will follow...

START RequestId: 25316010-3a23-40f8-9378-4d2ac6d6b17e Version: $LATEST
__  ____  __  _____   ___  __ ____  ______ 
--/ __ \/ / / / _ | / _ \/ //_/ / / / __/ 
-/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \   
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/   
2020-11-27 18:57:50,699 DEBUG [org.sor.lis.testapp-apiMain] (main) Starting...
2020-11-27 18:57:50,982 INFO  [io.quarkus] (main) testapp-api 0.0.3-SNAPSHOT native (powered by Quarkus 1.10.0.Final) started in 0.221s. 
2020-11-27 18:57:50,982 INFO  [io.quarkus] (main) Profile prod activated. 
2020-11-27 18:57:50,982 INFO  [io.quarkus] (main) Installed features: [amazon-lambda, cdi, resteasy, resteasy-jackson, smallrye-openapi]
END RequestId: 25316010-3a23-40f8-9378-4d2ac6d6b17e
REPORT RequestId: 25316010-3a23-40f8-9378-4d2ac6d6b17e  Duration: 10.15 ms  Billed Duration: 500 ms Memory Size: 1024 MB    Max Memory Used: 90 MB  Init Duration: 401.03 ms    
START RequestId: 8f7a99b5-e0a2-44b7-8ce8-05d7cf8809e8 Version: $LATEST
2020-11-27 18:57:51,068 INFO  [org.sor.lis.api.testapp-api] (executor-thread-1) Getting known apps
2020-11-27 18:57:51,168 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /apps failed, error id: 2304ba21-3204-49f6-be62-55694d3d9918-1: org.jboss.resteasy.spi.UnhandledException: java.lang.RuntimeException: Error injecting org.sorincos.testapp-api.StoreSecrets org.sorincos.testapp-api.api.ApiExecutor.secrets
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: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:136)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:40)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:97)
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:519)
at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
Caused by: java.lang.RuntimeException: Error injecting org.sorincos.testapp-api.StoreSecrets org.sorincos.testapp-api.api.ApiExecutor.secrets
at org.sorincos.testapp-api.api.ApiExecutor_Bean.create(ApiExecutor_Bean.zig:243)
at org.sorincos.testapp-api.api.ApiExecutor_Bean.create(ApiExecutor_Bean.zig:309)
at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:96)
at io.quarkus.arc.impl.AbstractSharedContext.access$000(AbstractSharedContext.java:14)
at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:29)
at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:26)
at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:26)
at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:17)
at org.sorincos.testapp-api.api.ApiExecutor_ClientProxy.arc$delegate(ApiExecutor_ClientProxy.zig:67)
at org.sorincos.testapp-api.api.ApiExecutor_ClientProxy.fetchKnownapps(ApiExecutor_ClientProxy.zig:357)
at org.sorincos.testapp-api.api.testapp-api.getapps(testapp-api.java:123)
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:643)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:507)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:457)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:459)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:419)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:393)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
... 19 more
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:84)
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 org.apache.http.conn.ssl.DefaultHostnameVerifier.<init>(DefaultHostnameVerifier.java:82)
at org.apache.http.conn.ssl.SSLConnectionSocketFactory.getDefaultHostnameVerifier(SSLConnectionSocketFactory.java:183)
at software.amazon.awssdk.http.apache.ApacheHttpClient$ApacheConnectionManagerFactory.getHostNameVerifier(ApacheHttpClient.java:622)
at software.amazon.awssdk.http.apache.ApacheHttpClient$ApacheConnectionManagerFactory.getPreferredSocketFactory(ApacheHttpClient.java:616)
at software.amazon.awssdk.http.apache.ApacheHttpClient$ApacheConnectionManagerFactory.create(ApacheHttpClient.java:594)
at software.amazon.awssdk.http.apache.ApacheHttpClient.createClient(ApacheHttpClient.java:153)
at software.amazon.awssdk.http.apache.ApacheHttpClient.<init>(ApacheHttpClient.java:127)
at software.amazon.awssdk.http.apache.ApacheHttpClient.<init>(ApacheHttpClient.java:106)
at software.amazon.awssdk.http.apache.ApacheHttpClient$DefaultBuilder.buildWithDefaults(ApacheHttpClient.java:586)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.lambda$null$3(SdkDefaultClientBuilder.java:273)
at java.util.Optional.map(Optional.java:265)
at software.amazon.awssdk.utils.Either.lambda$map$0(Either.java:51)
at java.util.Optional.orElseGet(Optional.java:369)
at software.amazon.awssdk.utils.Either.map(Either.java:51)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.lambda$resolveSyncHttpClient$4(SdkDefaultClientBuilder.java:273)
at java.util.Optional.map(Optional.java:265)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.resolveSyncHttpClient(SdkDefaultClientBuilder.java:273)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.finalizeSyncConfiguration(SdkDefaultClientBuilder.java:225)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.syncClientConfiguration(SdkDefaultClientBuilder.java:158)
at software.amazon.awssdk.services.ssm.DefaultSsmClientBuilder.buildClient(DefaultSsmClientBuilder.java:27)
at software.amazon.awssdk.services.ssm.DefaultSsmClientBuilder.buildClient(DefaultSsmClientBuilder.java:22)
at software.amazon.awssdk.core.client.builder.SdkDefaultClientBuilder.build(SdkDefaultClientBuilder.java:129)
at org.sorincos.testapp-api.aws.StoreClient.readSecrets(StoreClient.java:30)
at org.sorincos.testapp-api.aws.StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.create(StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.zig:122)
at org.sorincos.testapp-api.aws.StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.get(StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.zig:152)
at org.sorincos.testapp-api.aws.StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.get(StoreClient_ProducerMethod_readSecrets_7262248e4cb9334038e61d4f9fe73e01d1f1ff75_Bean.zig:187)
at org.sorincos.testapp-api.api.ApiExecutor_Bean.create(ApiExecutor_Bean.zig:226)
... 43 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(ClassLoader.java:275)
at org.apache.commons.logging.LogFactory.createFactory(LogFactory.java:1020)
... 75 more
END RequestId: 8f7a99b5-e0a2-44b7-8ce8-05d7cf8809e8
REPORT RequestId: 8f7a99b5-e0a2-44b7-8ce8-05d7cf8809e8  Duration: 116.37 ms Billed Duration: 200 ms Memory Size: 1024 MB    Max Memory Used: 98 MB  

[gsmet]

Are you sure you don't have a commons-logging jar around? Because that's the error I would have expected if you had the commons-logging jar around.

[gsmet]

Or commons-logging-api ?

[sorin-costea]

I do have a commons-logging around because I added it after seeing the very above exception :) and the same exception came. Maybe I should rather EXCLUDE it from the Elasticsearch and AWS SSM dependencies?

[gsmet]

So a few things:

• you should use our Elasticsearch high level client extension and it shouldn't come with commons-logging
• you should get rid of all the commons-logging dependencies and add commons-logging-jboss-logging instead
• if you have commons-logging around it will fail anyway because it uses LogFactoryImpl via reflection and if you don't do anything about it, LogFactoryImpl is not included in the native image.

If you exclude all the commons-logging dependencies and use commons-logging-jboss-logging, it will use the JBoss Logging infrastructure and everything is taken care of by Quarkus.

If you still have an issue after doing that, please try to come up with a reproducer.

[sorin-costea]

To use the Quarkus Elasticsearch client I must rewrite the entire code because the whole API is different. This is VERY unfortunate, to say at least...

[gsmet]

What do you mean by that? We use the official clients...

You can either use the low level one or the high level one depending on your needs.

And both are the official clients.

[sorin-costea]

My mistake above, I included the low level by mistake instead of the high level.
Still, I can't use an elasticsearch client configured via static properties (because dynamic host, request signing...) and I can't find any mention how to do it except that it was mentioned in your pull request discussion (which doesn't help me much)

[sorin-costea]

Ok forget that. I just produced my own RestHighLevelClient with @Named and there we go.
So basically what I needed was to:

• use the Quarkus Elasticsearch client (which I didn't know it existed)
• exclude commons-logging from the AWS SSM client (not obvious to me).

Thank you @gsmet !