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

java.lang.NoClassDefFoundError: Could not initialize class sun.net.www.protocol.https.DelegateHttpsURLConnection #3691

Open
TheCycoONE opened this issue Jun 19, 2024 · 14 comments
Labels
agent-java community Issues and PRs created by the community

Comments

@TheCycoONE
Copy link

TheCycoONE commented Jun 19, 2024

Describe the bug

This is an odd one, I'm seeing it in our k8s environments but not on my local machine and I don't have criteria for it, but it happens every time / with every war we're running.

{"@timestamp":"2024-06-18T17:45:53.353Z","ecs.version":"1.2.0","log.level":"INFO","message":"1 Spring WebApplicationInitializers detected on classpath","process.thread.name":"main","log.logger":"org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/rssweb]","@m":"1 Spring WebApplicationInitializers detected on classpath"}
Exception in thread "elastic-apm-remote-config-poller" java.lang.NoClassDefFoundError: Could not initialize class sun.net.www.protocol.https.DelegateHttpsURLConnection
	at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.<init>(HttpsURLConnectionImpl.java:82)
	at java.base/sun.net.www.protocol.https.Handler.openConnection(Handler.java:62)
	at java.base/sun.net.www.protocol.https.Handler.openConnection(Handler.java:57)
	at java.base/java.net.URL.openConnection(URL.java:1094)
	at co.elastic.apm.agent.util.UrlConnectionUtils.openUrlConnectionThreadSafely(UrlConnectionUtils.java:45)
	at co.elastic.apm.agent.report.ApmServerClient.startRequestToUrl(ApmServerClient.java:157)
	at co.elastic.apm.agent.report.ApmServerClient.execute(ApmServerClient.java:269)
	at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.fetchConfig(ApmServerConfigurationSource.java:169)
	at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.pollConfig(ApmServerConfigurationSource.java:139)
	at co.elastic.apm.agent.configuration.ApmServerConfigurationSource.access$000(ApmServerConfigurationSource.java:48)
	at co.elastic.apm.agent.configuration.ApmServerConfigurationSource$1.run(ApmServerConfigurationSource.java:125)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at co.elastic.apm.agent.util.ExecutorUtils$2.run(ExecutorUtils.java:99)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: java.lang.ExceptionInInitializerError: Exception java.lang.NoClassDefFoundError: Could not initialize class sun.net.www.protocol.http.HttpURLConnection [in thread "elastic-apm-server-healthcheck"]
	at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.<init>(HttpsURLConnectionImpl.java:82)
	at java.base/sun.net.www.protocol.https.Handler.openConnection(Handler.java:62)
	at java.base/sun.net.www.protocol.https.Handler.openConnection(Handler.java:57)
	at java.base/java.net.URL.openConnection(URL.java:1094)
	at co.elastic.apm.agent.util.UrlConnectionUtils.openUrlConnectionThreadSafely(UrlConnectionUtils.java:45)
	at co.elastic.apm.agent.report.ApmServerClient.startRequestToUrl(ApmServerClient.java:157)
	at co.elastic.apm.agent.report.ApmServerClient.executeForAllUrls(ApmServerClient.java:294)
	at co.elastic.apm.agent.report.ApmServerHealthChecker.call(ApmServerHealthChecker.java:67)

The jdk is:

openjdk 17.0.10 2024-01-16 LTS
OpenJDK Runtime Environment Corretto-17.0.10.8.1 (build 17.0.10+8-LTS)
OpenJDK 64-Bit Server VM Corretto-17.0.10.8.1 (build 17.0.10+8-LTS, mixed mode, sharing)

The server is Apache Tomcat/9.0.87

Elastic is configured through jvm arguments as follows:

-Delastic.apm.enabled=true -Delastic.apm.service_name=rssweb -Delastic.apm.application_packages=com.example -Delastic.apm.server_url=https://redacted.example.com/apm-server -Delastic.apm.api_key=<redacted> -Delastic.apm.environment=example -Delastic.apm.log_level=OFF -Delastic.apm.disable_instrumentations=spring-service-name -Delastic.apm.ignore_urls=*/about.html

Elastic apm agent is 1.50.0

@github-actions github-actions bot added agent-java community Issues and PRs created by the community triage labels Jun 19, 2024
@jackshirazi
Copy link
Contributor

I assume it's started with -javaagent:...

Can you try starting the agent with a delay, eg adding -Delastic.apm.delay_agent_premain_ms=10000 (that would bea 10 second delay) and see if the error is still present. We've seen a lot of race conditions with tomcat and starting the agent with a slight delay usually makes them go away

@TheCycoONE
Copy link
Author

Sorry no, this was programmatically attached in the WebApplicationInitializer of a Spring MVC war.

@JonasKunz
Copy link
Contributor

Sorry no, this was programmatically attached in the WebApplicationInitializer of a Spring MVC war.

Then can you delay this attachment (e.g. schedule it on a ScheduledExecutor with a 10 second delay) and see if the error still persists?

@TheCycoONE
Copy link
Author

With that delay we're seeing a different error


2024-07-01 09:06:27,825 [elastic-apm-server-healthcheck] ERROR co.elastic.apm.agent.util.ExecutorUtils - Could not initialize class sun.net.www.protocol.http.HttpURLConnection
java.lang.NoClassDefFoundError: Could not initialize class sun.net.www.protocol.http.HttpURLConnection
at sun.net.www.protocol.https.HttpsURLConnectionImpl.<init>(HttpsURLConnectionImpl.java:82) ~[?:?]
at sun.net.www.protocol.https.Handler.openConnection(Handler.java:62) ~[?:?]
at sun.net.www.protocol.https.Handler.openConnection(Handler.java:57) ~[?:?]
at java.net.URL.openConnection(URL.java:1094) ~[?:?]
at co.elastic.apm.agent.util.UrlConnectionUtils.openUrlConnectionThreadSafely(UrlConnectionUtils.java:45) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at co.elastic.apm.agent.report.ApmServerClient.startRequestToUrl(ApmServerClient.java:157) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at co.elastic.apm.agent.report.ApmServerClient.executeForAllUrls(ApmServerClient.java:294) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at co.elastic.apm.agent.report.ApmServerHealthChecker.call(ApmServerHealthChecker.java:67) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at co.elastic.apm.agent.report.ApmServerHealthChecker.call(ApmServerHealthChecker.java:42) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
at co.elastic.apm.agent.util.ExecutorUtils$2.run(ExecutorUtils.java:99) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.lang.ExceptionInInitializerError: Exception java.lang.ClassCastException: class org.apache.logging.log4j.core.async.RingBufferLogEventHandler cannot be cast to class com.lmax.disruptor.EventHandler (org.apache.logging.log4j.core.async.RingBufferLogEventHandler is in unnamed module of loader co.elastic.apm.agent.premain.ShadedClassLoader @244bae9d; com.lmax.disruptor.EventHandler is in unnamed module of loader 'app') [in thread "elastic-apm-metadata-1"]
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.createEventHandler(AsyncLoggerDisruptor.java:57) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.start(AsyncLoggerDisruptor.java:141) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.core.async.AsyncLoggerContext.start(AsyncLoggerContext.java:78) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:154) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:46) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:197) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:136) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.jul.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:34) ~[?:?]
at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:46) ~[elastic-apm-agent-51b912f34ae18b4e5ad349f50bc6fdd8-48ff69464528dd17e1f94c70696ecd41.jar:1.50.0]
at org.apache.logging.log4j.jul.LogManager.getLogger(LogManager.java:94) ~[?:?]
at java.util.logging.LogManager.demandSystemLogger(LogManager.java:574) ~[?:?]

We are logging tomcat with log4j2 not juli.

@JonasKunz
Copy link
Contributor

That is very weird. The agent internally uses log4j2 aswell, but it loads it in an isolated classloader.

java.util.logging is used internally by the JDK HttpUrlConnection class. It looks like that is bridged to log4j2 (I guess by your application / tomcat configuration?). During the initialization of that logger, something causes the log4j2s (the one from the app and the one from the agent) to get mixed up.

Just as a test/workaround, could you try adding Class.forName("sun.net.www.protocol.http.HttpURLConnection", true, getClass().getClassloader()) before you load the agent and see if it fixes the error?

@TheCycoONE
Copy link
Author

TheCycoONE commented Jul 3, 2024

@JonasKunz with that change the apm agent is working.

My full changes were:

 import co.elastic.apm.attach.ElasticApmAttacher;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.springframework.web.WebApplicationInitializer;
 import org.springframework.web.context.ContextLoaderListener;
 import org.springframework.web.context.support.AnnotationConfigWebApplicationContext;
 
 import javax.servlet.ServletContext;
+import java.util.concurrent.Executors;
+import java.util.concurrent.ScheduledExecutorService;
 
 public class WebAppInitializer implements WebApplicationInitializer {
+    private final ScheduledExecutorService scheduler = Executors.newScheduledThreadPool(1);
+    private static final Logger LOG = LogManager.getLogger(WebAppInitializer.class);
 
     @Override
     public void onStartup(ServletContext container) {
         if ("true".equalsIgnoreCase(System.getProperty("elastic.apm.enabled"))) {
-            ElasticApmAttacher.attach();
+            try {
+                Class.forName("sun.net.www.protocol.http.HttpURLConnection", true, getClass().getClassLoader());
+            } catch (ClassNotFoundException e) {
+                LOG.warn("TEST: Failed to load HttpURLConnection class", e);
+            }
+            scheduler.schedule(() -> ElasticApmAttacher.attach(), 10, java.util.concurrent.TimeUnit.SECONDS);
         }

@JonasKunz
Copy link
Contributor

I think you can also get rid of the delay with this workaround.

There must be something unusual around classloading in your setup, because we have many users (of which I'd assume many to have the log4j2-jul-bridge setup) with tomcat and haven't encountered this problem before. If you are able to provide a minimal sample project to reproduce this problem that would be great, this way we could attempt to fix the root cause.

@TheCycoONE
Copy link
Author

That may be a tricky ask, as I mentioned I haven't been able to reproduce outside of k8s yet; the same applications running on my local system with the same openjdk and tomcat versions do not reproduce. I'll see if I can get anywhere with docker...

@TheCycoONE
Copy link
Author

I made a docker image using the same tomcat base image that we deploy to k8s and the same application but wasn't able to reproduce there either unfortunately. We have paid support as well and I provided them with debug logs but it wasn't helpful.

This seems to be a very tricky case.

@jackshirazi
Copy link
Contributor

Do you have a workaround that's sufficiently valid for you? If so, we may just leave this as not priority

@TheCycoONE
Copy link
Author

TheCycoONE commented Jul 17, 2024

I am now able to reproduce in docker with a minimal application. The base tomcat and jdk images we use are not public so I don't yet have one I can share here; but we will be pursing it further with paid support. Otherwise the workaround @JonasKunz provided is sufficient for us.

@TheCycoONE
Copy link
Author

apmtest2.zip

Zip file contains a docker directory with Dockerfile and a very small JAVA application that can reproduce the issue.

@jackshirazi
Copy link
Contributor

Reproduces the issue, thanks!

@jackshirazi
Copy link
Contributor

The apache/logging-log4j2#2112 change in log4j2 (added in 2.23.0) changed how the lmax disruptor is handled. Because of how log4j2 initializes and how the agent initializes, there is a race condition in which classloader loads the various classes, and in this specific scenario it causes a failure where the class is loaded in both class loaders but an attempt is made to use the class from one classloader in the other.

The fix to revert to the log4j behaviour is simple but needs to be done in log4j2. A workaround in the agent would be the same as above (load sun.net.www.protocol.http.HttpURLConnection) early. We won't do that for now, but will review

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-java community Issues and PRs created by the community
Projects
None yet
Development

No branches or pull requests

3 participants