Merge pull request #1225 from DataDog/mconstantin/introduce-the-logs-handler

Introduce the LogsHandler

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

@@ -1,8 +1,5 @@
 package datadog.opentracing;
 
-import static io.opentracing.log.Fields.ERROR_OBJECT;
-import static io.opentracing.log.Fields.MESSAGE;
-
 import datadog.trace.api.DDTags;
 import datadog.trace.api.interceptor.MutableSpan;
 import datadog.trace.api.sampling.PrioritySampling;
@@ -50,6 +47,9 @@ public class DDSpan implements Span, MutableSpan {
    */
   private final AtomicLong durationNano = new AtomicLong();
 
+  /** Delegates to for handling the logs if present. */
+  private final LogHandler logHandler;
+
   /** Implementation detail. Stores the weak reference to this span. Used by TraceCollection. */
   volatile WeakReference<DDSpan> ref;
 
@@ -60,7 +60,19 @@ public class DDSpan implements Span, MutableSpan {
    * @param context the context used for the span
    */
   DDSpan(final long timestampMicro, final DDSpanContext context) {
+    this(timestampMicro, context, new DefaultLogHandler());
+  }
+
+  /**
+   * Spans should be constructed using the builder, not by calling the constructor directly.
+   *
+   * @param timestampMicro if greater than zero, use this time instead of the current time
+   * @param context the context used for the span
+   * @param logHandler as the handler where to delegate the log actions
+   */
+  DDSpan(final long timestampMicro, final DDSpanContext context, final LogHandler logHandler) {
     this.context = context;
+    this.logHandler = logHandler;
 
     if (timestampMicro <= 0L) {
       // record the start time
@@ -143,18 +155,6 @@ public class DDSpan implements Span, MutableSpan {
     setTag(DDTags.ERROR_STACK, errorString.toString());
   }
 
-  private boolean extractError(final Map<String, ?> map) {
-    if (map.get(ERROR_OBJECT) instanceof Throwable) {
-      final Throwable error = (Throwable) map.get(ERROR_OBJECT);
-      setErrorMeta(error);
-      return true;
-    } else if (map.get(MESSAGE) instanceof String) {
-      setTag(DDTags.ERROR_MSG, (String) map.get(MESSAGE));
-      return true;
-    }
-    return false;
-  }
-
   /* (non-Javadoc)
    * @see io.opentracing.BaseSpan#setTag(java.lang.String, java.lang.String)
    */
@@ -227,9 +227,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan log(final Map<String, ?> map) {
-    if (!extractError(map)) {
-      log.debug("`log` method is not implemented. Doing nothing");
-    }
+    logHandler.log(map, this);
     return this;
   }
 
@@ -238,9 +236,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan log(final long l, final Map<String, ?> map) {
-    if (!extractError(map)) {
-      log.debug("`log` method is not implemented. Doing nothing");
-    }
+    logHandler.log(l, map, this);
     return this;
   }
 
@@ -249,7 +245,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan log(final String s) {
-    log.debug("`log` method is not implemented. Provided log: {}", s);
+    logHandler.log(s, this);
     return this;
   }
 
@@ -258,7 +254,7 @@ public class DDSpan implements Span, MutableSpan {
    */
   @Override
   public final DDSpan log(final long l, final String s) {
-    log.debug("`log` method is not implemented. Provided log: {}", s);
+    logHandler.log(l, s, this);
     return this;
   }
 

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

@@ -580,6 +580,7 @@ public class DDTracer implements io.opentracing.Tracer, Closeable, datadog.trace
     private boolean errorFlag;
     private String spanType;
     private boolean ignoreScope = false;
+    private LogHandler logHandler = new DefaultLogHandler();
 
     public DDSpanBuilder(final String operationName, final ScopeManager scopeManager) {
       this.operationName = operationName;
@@ -593,7 +594,7 @@ public class DDTracer implements io.opentracing.Tracer, Closeable, datadog.trace
     }
 
     private Span startSpan() {
-      return new DDSpan(timestampMicro, buildSpanContext());
+      return new DDSpan(timestampMicro, buildSpanContext(), logHandler);
     }
 
     @Override
@@ -670,6 +671,13 @@ public class DDTracer implements io.opentracing.Tracer, Closeable, datadog.trace
       return parent.baggageItems();
     }
 
+    public DDSpanBuilder withLogHandler(final LogHandler logHandler) {
+      if (logHandler != null) {
+        this.logHandler = logHandler;
+      }
+      return this;
+    }
+
     @Override
     public DDSpanBuilder asChildOf(final Span span) {
       return asChildOf(span == null ? null : span.context());

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

@@ -0,0 +1,43 @@
+package datadog.opentracing;
+
+import static io.opentracing.log.Fields.ERROR_OBJECT;
+import static io.opentracing.log.Fields.MESSAGE;
+
+import datadog.trace.api.DDTags;
+import java.util.Map;
+import lombok.extern.slf4j.Slf4j;
+
+/** The default implementation of the LogHandler. */
+@Slf4j
+public class DefaultLogHandler implements LogHandler {
+  @Override
+  public void log(Map<String, ?> fields, DDSpan span) {
+    extractError(fields, span);
+    log.debug("`log` method is not implemented. Doing nothing");
+  }
+
+  @Override
+  public void log(long timestampMicroseconds, Map<String, ?> fields, DDSpan span) {
+    extractError(fields, span);
+    log.debug("`log` method is not implemented. Doing nothing");
+  }
+
+  @Override
+  public void log(String event, DDSpan span) {
+    log.debug("`log` method is not implemented. Provided log: {}", event);
+  }
+
+  @Override
+  public void log(long timestampMicroseconds, String event, DDSpan span) {
+    log.debug("`log` method is not implemented. Provided log: {}", event);
+  }
+
+  private void extractError(final Map<String, ?> map, DDSpan span) {
+    if (map.get(ERROR_OBJECT) instanceof Throwable) {
+      final Throwable error = (Throwable) map.get(ERROR_OBJECT);
+      span.setErrorMeta(error);
+    } else if (map.get(MESSAGE) instanceof String) {
+      span.setTag(DDTags.ERROR_MSG, (String) map.get(MESSAGE));
+    }
+  }
+}

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

@@ -0,0 +1,43 @@
+package datadog.opentracing;
+
+import java.util.Map;
+
+public interface LogHandler {
+
+  /**
+   * Handles the log implementation in the Span.
+   *
+   * @param fields key:value log fields. Tracer implementations should support String, numeric, and
+   *     boolean values; some may also support arbitrary Objects.
+   * @param span from which the call was made
+   */
+  void log(Map<String, ?> fields, DDSpan span);
+
+  /**
+   * Handles the log implementation in the Span.
+   *
+   * @param timestampMicroseconds The explicit timestamp for the log record. Must be greater than or
+   *     equal to the Span's start timestamp.
+   * @param fields key:value log fields. Tracer implementations should support String, numeric, and
+   * @param span from which the call was made
+   */
+  void log(long timestampMicroseconds, Map<String, ?> fields, DDSpan span);
+
+  /**
+   * Handles the log implementation in the Span..
+   *
+   * @param event the event value; often a stable identifier for a moment in the Span lifecycle
+   * @param span from which the call was made
+   */
+  void log(String event, DDSpan span);
+
+  /**
+   * Handles the log implementation in the Span.
+   *
+   * @param timestampMicroseconds The explicit timestamp for the log record. Must be greater than or
+   *     equal to the Span's start timestamp.
+   * @param event the event value; often a stable identifier for a moment in the Span lifecycle
+   * @param span from which the call was made
+   */
+  void log(long timestampMicroseconds, String event, DDSpan span);
+}

dd-trace-ot/src/test/groovy/datadog/opentracing/DDSpanBuilderTest.groovy

@@ -8,7 +8,6 @@ import datadog.trace.common.writer.ListWriter
 import datadog.trace.util.test.DDSpecification
 import io.opentracing.Scope
 import io.opentracing.noop.NoopSpan
-
 import static datadog.opentracing.DDSpanContext.ORIGIN_KEY
 import static java.util.concurrent.TimeUnit.MILLISECONDS
 
@@ -480,4 +479,164 @@ class DDSpanBuilderTest extends DDSpecification {
     "a:a,a:b,a:c" | [a: "c"]
     "a:1,b-c:d"   | [a: "1", "b-c": "d"]
   }
+
+  def "sanity test for logs if logHandler is null"() {
+    setup:
+    final String expectedName = "fakeName"
+
+    final DDSpan span =
+      tracer
+        .buildSpan(expectedName)
+        .withServiceName("foo")
+        .start()
+    final String expectedLogEvent = "fakeEvent"
+    final timeStamp = System.currentTimeMillis()
+    final Map<String, String> fieldsMap = new HashMap<>()
+
+    span.log(expectedLogEvent)
+    span.log(timeStamp, expectedLogEvent)
+    span.log(fieldsMap)
+    span.log(timeStamp, fieldsMap)
+  }
+
+  def "sanity test when passed log handler is null"() {
+    setup:
+    final String expectedName = "fakeName"
+    final DDSpan span = tracer
+      .buildSpan(expectedName)
+      .withLogHandler(null)
+      .start()
+    final String expectedLogEvent = "fakeEvent"
+    final timeStamp = System.currentTimeMillis()
+    final Map<String, String> fieldsMap = new HashMap<>()
+
+    span.log(expectedLogEvent)
+    span.log(timeStamp, expectedLogEvent)
+    span.log(fieldsMap)
+    span.log(timeStamp, fieldsMap)
+  }
+
+
+  def "should delegate simple logs to logHandler"() {
+    setup:
+    final LogHandler logHandler = new TestLogHandler()
+    final String expectedName = "fakeName"
+
+    final DDSpan span =
+      tracer
+        .buildSpan(expectedName)
+        .withLogHandler(logHandler)
+        .withServiceName("foo")
+        .start()
+    final String expectedLogEvent = "fakeEvent"
+    final timeStamp = System.currentTimeMillis()
+    span.log(timeStamp, expectedLogEvent)
+
+    expect:
+    logHandler.assertLogCalledWithArgs(timeStamp, expectedLogEvent, span)
+  }
+
+  def "should delegate simple logs with timestamp to logHandler"() {
+    setup:
+    final LogHandler logHandler = new TestLogHandler()
+    final String expectedName = "fakeName"
+
+    final DDSpan span =
+      tracer
+        .buildSpan(expectedName)
+        .withLogHandler(logHandler)
+        .withServiceName("foo")
+        .start()
+    final String expectedLogEvent = "fakeEvent"
+    span.log(expectedLogEvent)
+
+    expect:
+    logHandler.assertLogCalledWithArgs(expectedLogEvent, span)
+
+  }
+
+  def "should delegate logs with fields to logHandler"() {
+    setup:
+    final LogHandler logHandler = new TestLogHandler()
+    final String expectedName = "fakeName"
+
+    final DDSpan span =
+      tracer
+        .buildSpan(expectedName)
+        .withLogHandler(logHandler)
+        .withServiceName("foo")
+        .start()
+    final Map<String, String> fieldsMap = new HashMap<>()
+    span.log(fieldsMap)
+
+    expect:
+    logHandler.assertLogCalledWithArgs(fieldsMap, span)
+
+  }
+
+  def "should delegate logs with fields and timestamp to logHandler"() {
+    setup:
+    final LogHandler logHandler = new TestLogHandler()
+    final String expectedName = "fakeName"
+
+    final DDSpan span =
+      tracer
+        .buildSpan(expectedName)
+        .withLogHandler(logHandler)
+        .withServiceName("foo")
+        .start()
+    final Map<String, String> fieldsMap = new HashMap<>()
+    final timeStamp = System.currentTimeMillis()
+    span.log(timeStamp, fieldsMap)
+
+    expect:
+    logHandler.assertLogCalledWithArgs(timeStamp, fieldsMap, span)
+
+  }
+
+  private static class TestLogHandler implements LogHandler {
+    Object[] arguments = null
+
+    @Override
+    void log(Map<String, ?> fields, DDSpan span) {
+      arguments = new Object[2]
+      arguments[0] = fields
+      arguments[1] = span
+    }
+
+    @Override
+    void log(long timestampMicroseconds, Map<String, ?> fields, DDSpan span) {
+      arguments = new Object[3]
+      arguments[0] = timestampMicroseconds
+      arguments[1] = fields
+      arguments[2] = span
+    }
+
+    @Override
+    void log(String event, DDSpan span) {
+      arguments = new Object[2]
+      arguments[0] = event
+      arguments[1] = span
+    }
+
+    @Override
+    void log(long timestampMicroseconds, String event, DDSpan span) {
+      arguments = new Object[3]
+      arguments[0] = timestampMicroseconds
+      arguments[1] = event
+      arguments[2] = span
+    }
+
+    boolean assertLogCalledWithArgs(Object... args) {
+      if (arguments.size() != args.size()) {
+        return false
+      }
+      for (int i = 0; i < args.size(); i++) {
+        if (arguments[i] != args[i]) {
+          return false
+        }
+      }
+      return true
+    }
+  }
 }

dd-trace-ot/src/test/groovy/datadog/opentracing/DefaultLogHandlerTest.groovy

@@ -0,0 +1,80 @@
+package datadog.opentracing
+
+import datadog.trace.api.DDTags
+import datadog.trace.common.writer.ListWriter
+import io.opentracing.log.Fields
+import datadog.trace.util.test.DDSpecification
+
+
+class DefaultLogHandlerTest extends DDSpecification {
+  def writer = new ListWriter()
+  def tracer = DDTracer.builder().writer(writer).build()
+
+  def "handles correctly the error passed in the fields"() {
+    setup:
+    final LogHandler underTest = new DefaultLogHandler()
+    final DDSpan span = tracer.buildSpan("op name").withServiceName("foo").start()
+    final String errorMessage = "errorMessage"
+    final String differentMessage = "differentMessage"
+    final Throwable throwable = new Throwable(errorMessage)
+    final Map<String, ?> fields = new HashMap<>()
+    fields.put(Fields.ERROR_OBJECT, throwable)
+    fields.put(Fields.MESSAGE, differentMessage)
+
+    when:
+    underTest.log(fields, span)
+
+    then:
+    span.getTags().get(DDTags.ERROR_MSG) == throwable.getMessage()
+    span.getTags().get(DDTags.ERROR_TYPE) == throwable.getClass().getName()
+  }
+
+  def "handles correctly the error passed in the fields when called with timestamp"() {
+    setup:
+    final LogHandler underTest = new DefaultLogHandler()
+    final DDSpan span = tracer.buildSpan("op name").withServiceName("foo").start()
+    final String errorMessage = "errorMessage"
+    final String differentMessage = "differentMessage"
+    final Throwable throwable = new Throwable(errorMessage)
+    final Map<String, ?> fields = new HashMap<>()
+    fields.put(Fields.ERROR_OBJECT, throwable)
+    fields.put(Fields.MESSAGE, differentMessage)
+
+    when:
+    underTest.log(System.currentTimeMillis(), fields, span)
+
+    then:
+    span.getTags().get(DDTags.ERROR_MSG) == throwable.getMessage()
+    span.getTags().get(DDTags.ERROR_TYPE) == throwable.getClass().getName()
+  }
+
+  def "handles correctly the message passed in the fields"() {
+    setup:
+    final LogHandler underTest = new DefaultLogHandler()
+    final DDSpan span = tracer.buildSpan("op name").withServiceName("foo").start()
+    final String errorMessage = "errorMessage"
+    final Map<String, ?> fields = new HashMap<>()
+    fields.put(Fields.MESSAGE, errorMessage)
+
+    when:
+    underTest.log(fields, span)
+
+    then:
+    span.getTags().get(DDTags.ERROR_MSG) == errorMessage
+  }
+
+  def "handles correctly the message passed in the fields when called with timestamp"() {
+    setup:
+    final LogHandler underTest = new DefaultLogHandler()
+    final DDSpan span = tracer.buildSpan("op name").withServiceName("foo").start()
+    final String errorMessage = "errorMessage"
+    final Map<String, ?> fields = new HashMap<>()
+    fields.put(Fields.MESSAGE, errorMessage)
+
+    when:
+    underTest.log(System.currentTimeMillis(), fields, span)
+
+    then:
+    span.getTags().get(DDTags.ERROR_MSG) == errorMessage
+  }
+}