Logging improvements and other misc

from reviewing a customer’s logs.

dd-java-agent/agent-tooling/src/main/java/datadog/trace/agent/tooling/AgentInstaller.java

@@ -68,6 +68,7 @@ public class AgentInstaller {
             .or(nameStartsWith("org.groovy."))
             .or(nameStartsWith("com.p6spy."))
             .or(nameStartsWith("org.slf4j."))
+            .or(nameStartsWith("com.newrelic."))
             .or(nameContains("javassist"))
             .or(nameContains(".asm."))
             .or(nameMatches("com\\.mchange\\.v2\\.c3p0\\..*Proxy"));

dd-java-agent/instrumentation/servlet-2/src/main/java/datadog/trace/instrumentation/servlet2/Servlet2Advice.java

@@ -39,6 +39,9 @@ public class Servlet2Advice {
         GlobalTracer.get()
             .buildSpan("servlet.request")
             .asChildOf(extractedContext)
+            .withTag(Tags.COMPONENT.getKey(), "java-web-servlet")
+            .withTag(Tags.HTTP_METHOD.getKey(), httpServletRequest.getMethod())
+            .withTag(Tags.HTTP_URL.getKey(), httpServletRequest.getRequestURL().toString())
             .withTag(Tags.SPAN_KIND.getKey(), Tags.SPAN_KIND_SERVER)
             .withTag(DDTags.SPAN_TYPE, DDSpanTypes.WEB_SERVLET)
             .withTag("servlet.context", httpServletRequest.getContextPath())
@@ -48,12 +51,8 @@ public class Servlet2Advice {
       ((TraceScope) scope).setAsyncPropagation(true);
     }
 
-    final Span span = scope.span();
-    Tags.COMPONENT.set(span, "java-web-servlet");
-    Tags.HTTP_METHOD.set(span, httpServletRequest.getMethod());
-    Tags.HTTP_URL.set(span, httpServletRequest.getRequestURL().toString());
     if (httpServletRequest.getUserPrincipal() != null) {
-      span.setTag("user.principal", httpServletRequest.getUserPrincipal().getName());
+      scope.span().setTag("user.principal", httpServletRequest.getUserPrincipal().getName());
     }
     return scope;
   }

dd-java-agent/instrumentation/servlet-3/src/main/java/datadog/trace/instrumentation/servlet3/Servlet3Advice.java

@@ -39,6 +39,9 @@ public class Servlet3Advice {
         GlobalTracer.get()
             .buildSpan("servlet.request")
             .asChildOf(extractedContext)
+            .withTag(Tags.COMPONENT.getKey(), "java-web-servlet")
+            .withTag(Tags.HTTP_METHOD.getKey(), httpServletRequest.getMethod())
+            .withTag(Tags.HTTP_URL.getKey(), httpServletRequest.getRequestURL().toString())
             .withTag(Tags.SPAN_KIND.getKey(), Tags.SPAN_KIND_SERVER)
             .withTag(DDTags.SPAN_TYPE, DDSpanTypes.WEB_SERVLET)
             .withTag("servlet.context", httpServletRequest.getContextPath())
@@ -48,12 +51,8 @@ public class Servlet3Advice {
       ((TraceScope) scope).setAsyncPropagation(true);
     }
 
-    final Span span = scope.span();
-    Tags.COMPONENT.set(span, "java-web-servlet");
-    Tags.HTTP_METHOD.set(span, httpServletRequest.getMethod());
-    Tags.HTTP_URL.set(span, httpServletRequest.getRequestURL().toString());
     if (httpServletRequest.getUserPrincipal() != null) {
-      span.setTag("user.principal", httpServletRequest.getUserPrincipal().getName());
+      scope.span().setTag("user.principal", httpServletRequest.getUserPrincipal().getName());
     }
     return scope;
   }

dd-java-agent/instrumentation/spring-web/src/test/groovy/test/SpringBootBasedTest.groovy

@@ -30,8 +30,27 @@ class SpringBootBasedTest extends AgentTestRunner {
     restTemplate.getForObject("http://localhost:$port/", String) == "Hello World"
 
     and:
-    TEST_WRITER.waitForTraces(1)
+    assertTraces(TEST_WRITER, 1) {
-    TEST_WRITER.size() == 1
+      trace(0, 2) {
+        span(0) {
+          operationName "servlet.request"
+          resourceName "GET /"
+          spanType DDSpanTypes.WEB_SERVLET
+          parent()
+          errored false
+          tags {
+            "http.url" "http://localhost:$port/"
+            "http.method" "GET"
+            "span.kind" "server"
+            "span.type" "web"
+            "component" "java-web-servlet"
+            "http.status_code" 200
+            defaultTags()
+          }
+        }
+        controllerSpan(it, 1, "TestController.greeting")
+      }
+    }
   }
 
   def "generates spans"() {

dd-trace-ot/src/main/java/datadog/opentracing/DDSpan.java

@@ -87,6 +87,7 @@ public class DDSpan implements Span, MutableSpan {
   private void finishAndAddToTrace(final long durationNano) {
     // ensure a min duration of 1
     if (this.durationNano.compareAndSet(0, Math.max(1, durationNano))) {
+      log.debug("Finished: {}", this);
       context.getTrace().addSpan(this);
     } else {
       log.debug("{} - already finished!", this);
@@ -149,7 +150,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setTag(final String tag, final String value) {
-    this.context().setTag(tag, (Object) value);
+    context().setTag(tag, (Object) value);
     return this;
   }
 
@@ -158,7 +159,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setTag(final String tag, final boolean value) {
-    this.context().setTag(tag, (Object) value);
+    context().setTag(tag, (Object) value);
     return this;
   }
 
@@ -167,7 +168,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setTag(final String tag, final Number value) {
-    this.context().setTag(tag, (Object) value);
+    context().setTag(tag, (Object) value);
     return this;
   }
 
@@ -176,7 +177,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpanContext context() {
-    return this.context;
+    return context;
   }
 
   /* (non-Javadoc)
@@ -184,7 +185,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final String getBaggageItem(final String key) {
-    return this.context.getBaggageItem(key);
+    return context.getBaggageItem(key);
   }
 
   /* (non-Javadoc)
@@ -192,7 +193,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setBaggageItem(final String key, final String value) {
-    this.context.setBaggageItem(key, value);
+    context.setBaggageItem(key, value);
     return this;
   }
 
@@ -201,7 +202,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setOperationName(final String operationName) {
-    this.context().setOperationName(operationName);
+    context().setOperationName(operationName);
     return this;
   }
 
@@ -247,13 +248,13 @@ public class DDSpan implements Span, MutableSpan {
 
   @Override
   public final DDSpan setServiceName(final String serviceName) {
-    this.context().setServiceName(serviceName);
+    context().setServiceName(serviceName);
     return this;
   }
 
   @Override
   public final DDSpan setResourceName(final String resourceName) {
-    this.context().setResourceName(resourceName);
+    context().setResourceName(resourceName);
     return this;
   }
 
@@ -264,13 +265,13 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan setSamplingPriority(final int newPriority) {
-    this.context().setSamplingPriority(newPriority);
+    context().setSamplingPriority(newPriority);
     return this;
   }
 
   @Override
   public final DDSpan setSpanType(final String type) {
-    this.context().setSpanType(type);
+    context().setSpanType(type);
     return this;
   }
 
@@ -371,7 +372,7 @@ public class DDSpan implements Span, MutableSpan {
   @Override
   @JsonIgnore
   public Map<String, Object> getTags() {
-    return this.context().getTags();
+    return context().getTags();
   }
 
   @JsonGetter
@@ -405,12 +406,13 @@ public class DDSpan implements Span, MutableSpan {
       this(null);
     }
 
-    public UInt64IDStringSerializer(Class<String> stringClass) {
+    public UInt64IDStringSerializer(final Class<String> stringClass) {
       super(stringClass);
     }
 
     @Override
-    public void serialize(String value, JsonGenerator gen, SerializerProvider provider)
+    public void serialize(
+        final String value, final JsonGenerator gen, final SerializerProvider provider)
         throws IOException {
       gen.writeNumber(value);
     }

dd-trace-ot/src/main/java/datadog/opentracing/DDSpanContext.java

@@ -325,7 +325,7 @@ public class DDSpanContext implements io.opentracing.SpanContext {
   public String toString() {
     final StringBuilder s =
         new StringBuilder()
-            .append("Span [ t_id=")
+            .append("DDSpan [ t_id=")
             .append(traceId)
             .append(", s_id=")
             .append(spanId)

dd-trace-ot/src/main/java/datadog/opentracing/scopemanager/ContinuableScope.java

@@ -48,7 +48,7 @@ public class ContinuableScope implements Scope, TraceScope {
     this.continuation = continuation;
     this.spanUnderScope = spanUnderScope;
     this.finishOnClose = finishOnClose;
-    this.toRestore = scopeManager.tlsScope.get();
+    toRestore = scopeManager.tlsScope.get();
     scopeManager.tlsScope.set(this);
   }
 
@@ -96,6 +96,11 @@ public class ContinuableScope implements Scope, TraceScope {
     }
   }
 
+  @Override
+  public String toString() {
+    return super.toString() + "->" + spanUnderScope;
+  }
+
   public class Continuation implements Closeable, TraceScope.Continuation {
     public WeakReference<Continuation> ref;
 

dd-trace-ot/src/test/groovy/datadog/trace/DDSpanContextTest.groovy

@@ -18,7 +18,7 @@ class DDSpanContextTest extends Specification {
     context.serviceName == "fakeService"
     context.resourceName == "fakeResource"
     context.spanType == "fakeType"
-    context.toString() == "Span [ t_id=1, s_id=1, p_id=0] trace=fakeService/fakeOperation/fakeResource metrics={} *errored* tags={${extra}span.type=${context.getSpanType()}, thread.id=${Thread.currentThread().id}, thread.name=${Thread.currentThread().name}}"
+    context.toString() == "DDSpan [ t_id=1, s_id=1, p_id=0] trace=fakeService/fakeOperation/fakeResource metrics={} *errored* tags={${extra}span.type=${context.getSpanType()}, thread.id=${Thread.currentThread().id}, thread.name=${Thread.currentThread().name}}"
 
     where:
     name                 | extra             | tags
@@ -35,7 +35,7 @@ class DDSpanContextTest extends Specification {
     def thread = Thread.currentThread()
 
     def expectedTags = [(DDTags.THREAD_NAME): thread.name, (DDTags.THREAD_ID): thread.id, (DDTags.SPAN_TYPE): context.getSpanType()]
-    def expectedTrace = "Span [ t_id=1, s_id=1, p_id=0] trace=$details metrics={} tags={span.type=${context.getSpanType()}, thread.id=$thread.id, thread.name=$thread.name}"
+    def expectedTrace = "DDSpan [ t_id=1, s_id=1, p_id=0] trace=$details metrics={} tags={span.type=${context.getSpanType()}, thread.id=$thread.id, thread.name=$thread.name}"
 
     expect:
     context.getTags() == expectedTags
@@ -62,7 +62,7 @@ class DDSpanContextTest extends Specification {
       (DDTags.THREAD_NAME): thread.name,
       (DDTags.THREAD_ID)  : thread.id
     ]
-    context.toString() == "Span [ t_id=1, s_id=1, p_id=0] trace=fakeService/fakeOperation/fakeResource metrics={} tags={span.type=${context.getSpanType()}, $name=$value, thread.id=$thread.id, thread.name=$thread.name}"
+    context.toString() == "DDSpan [ t_id=1, s_id=1, p_id=0] trace=fakeService/fakeOperation/fakeResource metrics={} tags={span.type=${context.getSpanType()}, $name=$value, thread.id=$thread.id, thread.name=$thread.name}"
 
     where:
     name             | value