Instrumentation broken with OpenTracing on classpath

[praseodym]

We currently have a Spring app that has Datadog APM tracing set up using the Java agent. The app runs on Tomcat and uses JDBC and Apache HttpClient, both of which are instrumented by the agent. We also use the dd-trace-api dependency to manually mark methods for instrumentation using the @Trace annotation:

<dependency>
    <groupId>com.datadoghq</groupId>
    <artifactId>dd-trace-api</artifactId>
    <version>0.17.0</version>
</dependency>

To get more granular trace spans, we want to use OpenTracing as recommended by the docs. We set up the required dependencies:

<dependency>
    <groupId>io.opentracing</groupId>
    <artifactId>opentracing-api</artifactId>
    <version>0.31.0</version>
</dependency>
<dependency>
    <groupId>io.opentracing</groupId>
    <artifactId>opentracing-util</artifactId>
    <version>0.31.0</version>
</dependency>

After this, tracing of both JDBC and Apache HttpClient calls stopped working, even without any tracer.buildSpan calls in the app.

Looking at the debug output of the Java agent (-Ddatadog.slf4j.simpleLogger.defaultLogLevel=debug) confirms that something is off. This is the 'Applying instrumentation' output from an instance without the OpenTracing libraries on the classpath vs. with them:

'Applying instrumentation' output without OpenTracing (OK)

[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ThreadPoolExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: spring-web -- datadog.trace.instrumentation.springweb.HandlerAdapterInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: spring-web -- datadog.trace.instrumentation.springweb.HandlerAdapterInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: spring-web -- datadog.trace.instrumentation.springweb.HandlerAdapterInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: spring-web -- datadog.trace.instrumentation.springweb.HandlerAdapterInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: spring-web -- datadog.trace.instrumentation.springweb.DispatcherServletInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on java.net.URLClassLoader@56673b2c
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: trace -- datadog.trace.instrumentation.trace_annotation.TraceAnnotationsInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: trace -- datadog.trace.instrumentation.trace_annotation.TraceAnnotationsInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[PostgreSQL JDBC driver connection thread] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.ConnectionInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jdbc -- datadog.trace.instrumentation.jdbc.StatementInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: httpclient -- datadog.trace.instrumentation.apachehttpclient.ApacheHttpClientInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: httpclient -- datadog.trace.instrumentation.apachehttpclient.ApacheHttpClientInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: httpclient -- datadog.trace.instrumentation.apachehttpclient.ApacheHttpClientInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: httpclient -- datadog.trace.instrumentation.apachehttpclient.ApacheHttpClientInstrumentation on ParallelWebappClassLoader
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: httpclient -- datadog.trace.instrumentation.apachehttpclient.ApacheHttpClientInstrumentation on ParallelWebappClassLoader

'Applying instrumentation' output with OpenTracing (broken)

[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ThreadPoolExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on java.net.URLClassLoader@5c44c582
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on java.net.URLClassLoader@5c44c582
[main] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on java.net.URLClassLoader@5c44c582
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.FilterChain3Instrumentation on java.net.URLClassLoader@5c44c582
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jsp -- datadog.trace.instrumentation.jsp.JasperJSPCompilationContextInstrumentation on java.net.URLClassLoader@5c44c582
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: jsp -- datadog.trace.instrumentation.jsp.JSPInstrumentation on java.net.URLClassLoader@5c44c582
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: servlet -- datadog.trace.instrumentation.servlet3.HttpServlet3Instrumentation on java.net.URLClassLoader@5c44c582
[http-nio-8080-exec-8] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.ExecutorInstrumentation on null
[http-nio-8080-exec-8] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null
[http-nio-8080-exec-8] DEBUG datadog.trace.agent.tooling.Instrumenter$Default - Applying instrumentation: java_concurrent -- datadog.trace.instrumentation.java.concurrent.FutureInstrumentation on null

As can be seen from the logs, there is no instrumentation for spring-web, jdbc and httpclient when OpenTracing is on the classpath.

One thing that stands out is the following errors that appear in the logs when OpenTracing is added:

[main] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - loader ParallelWebappClassLoader
  context: ROOT
  delegate: false
----------> Parent Classloader:
java.net.URLClassLoader@5c44c582
 failed to delegate bootstrap opentracing class
--
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - loader org.apache.jasper.servlet.JasperLoader@5b2ba8f0 failed to delegate bootstrap opentracing class
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - skipping classloader instance org.apache.jasper.servlet.JasperLoader@5b2ba8f0 of type org.apache.jasper.servlet.JasperLoader
--
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - loader org.apache.jasper.servlet.JasperLoader@43f9f2c7 failed to delegate bootstrap opentracing class
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - skipping classloader instance org.apache.jasper.servlet.JasperLoader@43f9f2c7 of type org.apache.jasper.servlet.JasperLoader
--
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - loader org.apache.jasper.servlet.JasperLoader@4999d5ad failed to delegate bootstrap opentracing class
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - skipping classloader instance org.apache.jasper.servlet.JasperLoader@4999d5ad of type org.apache.jasper.servlet.JasperLoader
--
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - loader org.apache.jasper.servlet.JasperLoader@4f7a84de failed to delegate bootstrap opentracing class
[http-nio-8080-exec-1] DEBUG datadog.trace.agent.tooling.ClassLoaderMatcher - skipping classloader instance org.apache.jasper.servlet.JasperLoader@4f7a84de of type org.apache.jasper.servlet.JasperLoader

I'm not quite sure what the cause of this behaviour is. Maybe #433 is related?

[realark]

The root cause is classpath related. The loader ParallelWebappClassLoader has a delegate: false property. What this means is that spring boot's classloader will load OT without delegating to the parent (bootstrap) loader. This will actually cause two different sets of OpenTracing classes to appear at runtime. One will be the OT classes used by Datadog, and the other the OT classes loaded by spring-boot.

The Datadog instrumentation notices this setup and backs its instrumentation off because injecting instrumentation in that scenario won't have the desired effect.

I realize this isn't a good "out of the box" experience. We're working on a long-term fix for these type of classloading scenarios.

In the meantime either one of these workarounds can be used:

• Configure the web classloaders with delegate=true: https://qiita.com/tkprof/items/b92d3a245045480afd26
• Put the OpenTracing classes on the system classpath instead of the web classpath

[praseodym]

Thanks for the information! Since this is a traditional Spring app deployed to Tomcat as a WAR file it was easy to just add <Loader delegate="true"/> to the Tomcat context.xml. This has fixed the problem.

I'll leave this issue open to because the out-of-box experience could indeed use some improvement, but feel free to close it if this is already tracked somewhere else.

[realark]

It's fine to leave this open. We'll track this and close it out when the fix lands. Thanks for confirming the workaround!

[tylerbenson]

I think this is solved in 0.25.0+ with #741. Closing. Please reopen if still a problem.