diff --git a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Examples.java b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Examples.java index 2e1603d7107..136eec748a4 100644 --- a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Examples.java +++ b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Examples.java @@ -1,7 +1,7 @@ package datadog.trace.tracer.ext; +import datadog.trace.tracer.Continuation; import datadog.trace.tracer.Span; -import datadog.trace.tracer.Trace; import datadog.trace.tracer.Tracer; // Keeping in PR for potential discussions. Will eventually remove. @@ -18,9 +18,8 @@ public static void test() { final TracerContext ctx = TracerContext.getGlobalContext(); // without try-with-resources { - Span rootSpan = ctx.getTracer().buildTrace(null); + final Span rootSpan = ctx.getTracer().buildTrace(null); final Scope scope = ctx.pushScope(rootSpan); - rootSpan.setError(true); rootSpan.attachThrowable(someThrowable); scope.close(); rootSpan.finish(); @@ -44,11 +43,10 @@ public static void test() { // with try-with-resources finishOnClose=false { - Span rootSpan = ctx.getTracer().buildTrace(null); - try (Scope scope = ctx.pushScope(rootSpan)) { + final Span rootSpan = ctx.getTracer().buildTrace(null); + try (final Scope scope = ctx.pushScope(rootSpan)) { // the body - } catch (Throwable t) { - rootSpan.setError(true); + } catch (final Throwable t) { rootSpan.attachThrowable(t); throw t; } finally { @@ -58,10 +56,10 @@ public static void test() { // continuations { - Span rootSpan = ctx.getTracer().buildTrace(null); - final Trace.Continuation cont = rootSpan.getTrace().createContinuation(rootSpan); + final Span rootSpan = ctx.getTracer().buildTrace(null); + final Continuation cont = rootSpan.getTrace().createContinuation(rootSpan); { // on another thread - final Span parent = cont.span(); + final Span parent = cont.getSpan(); try { // body } finally { @@ -71,6 +69,7 @@ public static void test() { } // create a span as a child of the currently active span - Span childSpan = ctx.peekScope().span().getTrace().createSpan(ctx.peekScope().span()); + final Span childSpan = + ctx.peekScope().span().getTrace().createSpan(ctx.peekScope().span().getContext()); } } diff --git a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Scope.java b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Scope.java index 26948229297..d74615a57b9 100644 --- a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Scope.java +++ b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/Scope.java @@ -1,14 +1,14 @@ package datadog.trace.tracer.ext; +import datadog.trace.tracer.Continuation; import datadog.trace.tracer.Span; -import datadog.trace.tracer.Trace; /** * A scope holds a single span or trace continuation and may optionally finish its span or * continuation. * *

To create a scope, see {@link TracerContext#pushScope(Span)} and {@link - * TracerContext#pushScope(Trace.Continuation)}. + * TracerContext#pushScope(Continuation)}. * *

All created scopes must be closed with {@link Scope#close()} */ @@ -22,5 +22,6 @@ public interface Scope extends AutoCloseable { *

Attempting to close a scope which is not on the top of its TracerContext's scope-stack is an * error. See {@link TracerContext#peekScope()}. */ + @Override void close(); } diff --git a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/TracerContext.java b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/TracerContext.java index a14cfdfe640..e8d78b7b3f6 100644 --- a/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/TracerContext.java +++ b/dd-trace-ext/src/main/java/datadog/trace/tracer/ext/TracerContext.java @@ -1,7 +1,7 @@ package datadog.trace.tracer.ext; +import datadog.trace.tracer.Continuation; import datadog.trace.tracer.Span; -import datadog.trace.tracer.Trace; import datadog.trace.tracer.Tracer; /** @@ -27,7 +27,7 @@ public static TracerContext getGlobalContext() { * @return The old global TracerContext, or null if no previous context ws registered */ public static TracerContext registerGlobalContext( - TracerContext context, boolean replaceExisting) { + final TracerContext context, final boolean replaceExisting) { return null; } @@ -38,7 +38,7 @@ public static boolean isRegistered() { private final Tracer tracer; - public TracerContext(Tracer tracer) { + public TracerContext(final Tracer tracer) { this.tracer = tracer; } @@ -55,7 +55,7 @@ public Tracer getTracer() { * @param span * @return */ - public Scope pushScope(Span span) { + public Scope pushScope(final Span span) { return null; } @@ -66,7 +66,7 @@ public Scope pushScope(Span span) { * @param continuation * @return */ - public Scope pushScope(Trace.Continuation continuation) { + public Scope pushScope(final Continuation continuation) { return null; } @@ -77,7 +77,7 @@ public Scope pushScope(Trace.Continuation continuation) { * * @param scope the topmost scope in the scope stack. */ - public void popScope(Scope scope) {} + public void popScope(final Scope scope) {} /** @return The scope on the top of this scope-stack or null if there is no active scope. */ public Scope peekScope() { diff --git a/dd-trace/dd-trace.gradle b/dd-trace/dd-trace.gradle index 64f4a8f7697..11166de0740 100644 --- a/dd-trace/dd-trace.gradle +++ b/dd-trace/dd-trace.gradle @@ -5,6 +5,7 @@ dependencies { annotationProcessor deps.autoservice implementation deps.autoservice + compile project(':dd-java-agent:agent-bootstrap') compile project(':dd-trace-api') compile deps.jackson @@ -12,4 +13,9 @@ dependencies { // any higher versions seems to break ES tests with this exception: // java.lang.NoSuchMethodError: com.fasterxml.jackson.dataformat.smile.SmileGenerator.getOutputContext() compile group: 'org.msgpack', name: 'jackson-dataformat-msgpack', version: '0.8.14' + + // Spock uses that for mocking + testCompile deps.bytebuddy + testCompile group: 'org.objenesis', name: 'objenesis', version: '2.6' // Last version to support Java7 + testCompile group: 'nl.jqno.equalsverifier', name: 'equalsverifier', version: '2.5.2' // Last version to support Java7 } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Clock.java b/dd-trace/src/main/java/datadog/trace/tracer/Clock.java index 22bfd417045..656e6c80fc4 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/Clock.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/Clock.java @@ -1,34 +1,59 @@ package datadog.trace.tracer; import java.util.concurrent.TimeUnit; +import lombok.EqualsAndHashCode; /** - * A simple wrapper for system clock that aims to provide the current time - * - *

- * - *

- * - *

+ * This is a wrapper to System clock that provides an easier way to get nanosecond precision. * *

The JDK provides two clocks: *

  • one in nanoseconds, for precision, but it can only use to measure durations *
  • one in milliseconds, for accuracy, useful to provide epoch time * - *

    + *

    Once created this class captures current time with millisecond presition and current + * nanosecond counter. * - *

    At this time, we are using a millis precision (converted to micros) in order to guarantee - * consistency between the span start times and the durations + *

    It provides an API to create {@link Timestamp} that can be used to measure durations with + * nanosecond precision. */ +@EqualsAndHashCode public class Clock { + /** Tracer that created this clock */ + private final Tracer tracer; + + /** Trace start time in nano seconds measured up to a millisecond accuracy */ + private final long startTimeNano; + /** Nano ticks counter when clock is created */ + private final long startNanoTicks; + + public Clock(final Tracer tracer) { + this.tracer = tracer; + startTimeNano = epochTimeNano(); + startNanoTicks = nanoTicks(); + } + + /** @return {@link Tracer} that created this clock. */ + public Tracer getTracer() { + return tracer; + } + + /** + * Create new timestamp instance for current time. + * + * @return new timestamp capturing current time. + */ + public Timestamp createCurrentTimestamp() { + return new Timestamp(this); + } + /** - * Get the current nanos ticks (i.e. System.nanonTime()), this method can't be use for date - * accuracy (only duration calculations) + * Get the current nanos ticks (i.e. System.nanoTime()), this method can't be use for date + * accuracy (only duration calculations). * - * @return The current nanos ticks + * @return The current nanos ticks. */ - public static long nanoTime() { + long nanoTicks() { return System.nanoTime(); } @@ -37,20 +62,38 @@ public static long nanoTime() { * *

    Note: The actual precision is the millis. * - * @return the current epoch time in micros + * @return the current epoch time in micros. */ - public static long epochTimeMicro() { + long epochTimeMicro() { return TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis()); } /** * Get the current epoch time in nanos. * - *

    Note: The actual precision is the millis. This will overflow ~290 years after epoch + *

    Note: The actual precision is the millis. This will overflow ~290 years after epoch. * - * @return the current epoch time in nanos + * @return the current epoch time in nanos. */ - public static long epochTimeNano() { + long epochTimeNano() { return TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis()); } + + /** + * Get time this clock instance was created in nanos. + * + * @return the time this clock instance was created in nanos. + */ + long getStartTimeNano() { + return startTimeNano; + } + + /** + * Get nano ticks counter value when this clock instance was created. + * + * @return nano ticks counter value when this clock instance was created. + */ + long getStartNanoTicks() { + return startNanoTicks; + } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Continuation.java b/dd-trace/src/main/java/datadog/trace/tracer/Continuation.java new file mode 100644 index 00000000000..823a1085589 --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/Continuation.java @@ -0,0 +1,26 @@ +package datadog.trace.tracer; + +/** + * Continuations are used to prevent a trace from reporting without creating a span. + * + *

    All spans are thread safe. + * + *

    To create a Span, see {@link Trace#createContinuation(Span parentSpan)} + */ +public interface Continuation { + + /** @return parent span used to create this continuation. */ + Span getSpan(); + + /** @return trace used to create this continuation. */ + Trace getTrace(); + + /** @return true iff continuation has been closed. */ + boolean isClosed(); + + /** + * Close the continuation. Continuation's trace will not block reporting on account of this + * continuation. + */ + void close(); +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/ContinuationImpl.java b/dd-trace/src/main/java/datadog/trace/tracer/ContinuationImpl.java new file mode 100644 index 00000000000..4733ae9b7e6 --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/ContinuationImpl.java @@ -0,0 +1,74 @@ +package datadog.trace.tracer; + +import lombok.extern.slf4j.Slf4j; + +/** Concrete implementation of a continuation */ +@Slf4j +class ContinuationImpl implements Continuation { + + private final TraceInternal trace; + private final Span span; + private volatile boolean closed = false; + + ContinuationImpl(final TraceInternal trace, final Span span) { + this.trace = trace; + this.span = span; + } + + @Override + public Trace getTrace() { + return trace; + } + + @Override + public Span getSpan() { + return span; + } + + @Override + public boolean isClosed() { + return closed; + } + + @Override + public synchronized void close() { + if (closed) { + reportUsageError("Attempted to close continuation that is already closed: %s", this); + } else { + closeContinuation(false); + } + } + + @Override + protected synchronized void finalize() { + try { + if (!closed) { + trace + .getTracer() + .reportWarning( + "Closing continuation due to GC, this will prevent trace from being reported: %s", + this); + closeContinuation(true); + } + } catch (final Throwable t) { + // Exceptions thrown in finalizer are eaten up and ignored, so log them instead + log.debug("Span finalizer had thrown an exception: ", t); + } + } + + /** + * Helper method to perform operations needed to close the continuation. + * + *

    Note: This has to be called under object lock. + * + * @param invalid true iff continuation is being closed due to GC, this will make trace invalid. + */ + private void closeContinuation(final boolean invalid) { + closed = true; + trace.closeContinuation(this, invalid); + } + + private void reportUsageError(final String message, final Object... args) { + trace.getTracer().reportError(message, args); + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Interceptor.java b/dd-trace/src/main/java/datadog/trace/tracer/Interceptor.java new file mode 100644 index 00000000000..77271f9dcaf --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/Interceptor.java @@ -0,0 +1,29 @@ +package datadog.trace.tracer; + +/** + * An Interceptor allows adding hooks to particular events of a span starting and finishing and also + * trace being written to backend. + */ +public interface Interceptor { + /** + * Called after a span is started. + * + * @param span the started span. + */ + void afterSpanStarted(Span span); + + /** + * Called before a span is finished. + * + * @param span the span to be finished. + */ + void beforeSpanFinished(Span span); + + /** + * Invoked when a trace is eligible for writing but hasn't been handed off to its writer yet. + * + * @param trace The intercepted trace. + * @return modified trace. Null if trace is to be dropped. + */ + Trace beforeTraceWritten(Trace trace); +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Span.java b/dd-trace/src/main/java/datadog/trace/tracer/Span.java index ff41aee9585..4aa16a06b7e 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/Span.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/Span.java @@ -5,113 +5,131 @@ * *

    All spans are thread safe. * - *

    To create a Span, see {@link Tracer#buildTrace()} + *

    To create a Span, see {@link Trace#createSpan(SpanContext parentContext, Timestamp + * startTimestamp)} */ public interface Span { /** @return The trace this span is associated with. */ Trace getTrace(); - /** Stop the span's timer. Has no effect if the span is already finished. */ - void finish(); + /** @return start timestamp of this span */ + public Timestamp getStartTimestamp(); - /** - * Stop the span's timer. Has no effect if the span is already finished. - * - *

    It's undefined behavior to specify a finish timestamp which occurred before this span's - * start timestamp. - * - * @param finishTimestampNanoseconds Epoch time in nanoseconds. - */ - void finish(long finishTimestampNanoseconds); + /** @return duration of this span in nanoseconds or null if span is not finished */ + public Long getDuration(); - /** Returns true if a finish method has been invoked on this span. */ + /** @return true if a finish method has been invoked on this span. */ boolean isFinished(); /** - * Get the span context for this span. + * Get the span context for this span - required attributes to report to datadog. + * + *

    See https://docs.datadoghq.com/api/?lang=python#tracing * * @return the span context. */ SpanContext getContext(); + /** @return the span's service. */ + String getService(); + /** - * Get a meta value on a span. + * Set the span's service. * - * @param key The meta key - * @return The value currently associated with the given key. Null if no associated. TODO: can - * return null + *

    May not exceed 100 characters. + * + * @param service the new service for the span. */ - Object getMeta(String key); + void setService(String service); + + /** @return the span's resource. */ + String getResource(); /** - * Set key-value metadata on the span. + * Span the span's resource (e.g. http endpoint). * - *

    TODO: Forbid setting null? + *

    May not exceed 5000 characters. + * + * @param resource the new resource for the span. */ - void setMeta(String key, String value); + void setResource(String resource); - /** {@link Span#setMeta(String, String)} for boolean values */ - void setMeta(String key, boolean value); + /** @return the span's type. */ + String getType(); - /** {@link Span#setMeta(String, String)} for number values */ - void setMeta(String key, Number value); + /** + * Set the span's type (web, db, etc). {@see DDSpanTypes}. + * + * @param type the new type of the span. + */ + void setType(String type); - /** Get the span's name */ + /** @return the span's name. */ String getName(); + /** * Set the span's name. * - * @param newName the new name for the span. + *

    May not exceed 100 characters. + * + * @param name the new name for the span. */ - void setName(String newName); + void setName(String name); - String getResource(); + /** @return true iff span was marked as error span. */ + boolean isErrored(); - void setResource(String newResource); + /** + * Mark the span as having an error. + * + * @param errored true if the span has an error. + */ + void setErrored(boolean errored); - String getService(); + /** */ + /** + * Attach a throwable to this span. + * + * @param throwable throwable to attach + */ + void attachThrowable(Throwable throwable); - void setService(String newService); + /** + * Get a meta value on a span. + * + * @param key The meta key + * @return The value currently associated with the given key. Null if no associated. + */ + Object getMeta(String key); - String getType(); + /** + * Set key-value metadata on the span. + * + * @param key to set + * @param value to set + */ + void setMeta(String key, String value); - void setType(String newType); + /** {@link Span#setMeta(String, String)} for boolean values */ + void setMeta(String key, Boolean value); - boolean isErrored(); + /** {@link Span#setMeta(String, String)} for number values */ + void setMeta(String key, Number value); - /** Attach a throwable to this span. */ - void attachThrowable(Throwable t); + /** Stop the span's timer. Has no effect if the span is already finished. */ + void finish(); /** - * Mark the span as having an error. + * Stop the span's timer. Has no effect if the span is already finished. * - * @param isErrored true if the span has an error. + *

    It's undefined behavior to specify a finish timestamp which occurred before this span's + * start timestamp. + * + * @param finishTimestampNanoseconds Epoch time in nanoseconds. */ - void setError(boolean isErrored); + void finish(long finishTimestampNanoseconds); // TODO: OpenTracing Span#log methods. Do we need something here to support them? Current DDSpan // does not implement. - - /** - * A Interceptor allows adding hooks to particular events between a span starting and finishing. - */ - interface Interceptor { - /** - * Called after a span is started. - * - * @param span the started span - */ - void spanStarted(Span span); - - /** Called after a span's metadata is updated. */ - void afterMetadataSet(Span span, Object key, Object value); - - /** - * Called after a span is finished. - * - * @param span the started span - */ - void spanFinished(Span span); - } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/SpanContext.java b/dd-trace/src/main/java/datadog/trace/tracer/SpanContext.java index d3ad805ef1f..d71137058f0 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/SpanContext.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/SpanContext.java @@ -8,12 +8,13 @@ *

    All SpanContexts are thread safe. */ public interface SpanContext { + /** - * Get this context's span id. + * Get this context's trace id. * * @return 64 bit unsigned integer in String format. */ - String getSpanId(); + String getTraceId(); /** * Get this context's parent span id. @@ -23,11 +24,11 @@ public interface SpanContext { String getParentId(); /** - * Get this context's trace id. + * Get this context's span id. * * @return 64 bit unsigned integer in String format. */ - String getTraceId(); + String getSpanId(); /** * Get the sampling flag for this context. diff --git a/dd-trace/src/main/java/datadog/trace/tracer/SpanContextImpl.java b/dd-trace/src/main/java/datadog/trace/tracer/SpanContextImpl.java new file mode 100644 index 00000000000..0aaccbff941 --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/SpanContextImpl.java @@ -0,0 +1,61 @@ +package datadog.trace.tracer; + +import datadog.trace.api.sampling.PrioritySampling; +import java.util.concurrent.ThreadLocalRandom; +import lombok.EqualsAndHashCode; + +@EqualsAndHashCode +class SpanContextImpl implements SpanContext { + + public static final String ZERO = "0"; + + private final String traceId; + private final String parentId; + private final String spanId; + + SpanContextImpl(final String traceId, final String parentId, final String spanId) { + this.traceId = traceId; + this.parentId = parentId; + this.spanId = spanId; + } + + @Override + public String getTraceId() { + return traceId; + } + + @Override + public String getParentId() { + return parentId; + } + + @Override + public String getSpanId() { + return spanId; + } + + // TODO: Implement proper priority handling methods + @Override + public Integer getSamplingFlags() { + return PrioritySampling.SAMPLER_KEEP; + } + + static SpanContext fromParent(final SpanContext parent) { + final String traceId; + final String parentId; + if (parent == null) { + traceId = generateNewId(); + parentId = ZERO; + } else { + traceId = parent.getTraceId(); + parentId = parent.getSpanId(); + } + return new SpanContextImpl(traceId, parentId, generateNewId()); + } + + static String generateNewId() { + // TODO: expand the range of numbers generated to be from 1 to uint 64 MAX + // Ensure the generated ID is in a valid range: + return String.valueOf(ThreadLocalRandom.current().nextLong(1, Long.MAX_VALUE)); + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/SpanImpl.java b/dd-trace/src/main/java/datadog/trace/tracer/SpanImpl.java index 339ad0c8a82..3a21cc03edc 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/SpanImpl.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/SpanImpl.java @@ -1,138 +1,266 @@ package datadog.trace.tracer; +import datadog.trace.api.DDTags; +import java.io.PrintWriter; +import java.io.StringWriter; +import java.util.HashMap; import java.util.List; import java.util.Map; -import java.util.concurrent.atomic.AtomicLong; - -public class SpanImpl implements Span { - private final Clock clock = null; - private final Trace trace = null; - // See See https://docs.datadoghq.com/api/?lang=python#tracing - // Required attributes to report to datadog. - private final SpanContext context = null; - /* Span name. May not exceed 100 characters. */ - private final String name = ""; - /* Span resource (e.g. http endpoint). May not exceed 5000 characters. */ - private final String resource = ""; - /* Span service. May not exceed 100 characters. */ - private final String service = ""; - /* The start time of the request in nanoseconds from the unix epoch. */ - private final long startEpochNano = -1; - /* Duration of the span in nanoseconds */ - private final AtomicLong durationNano = new AtomicLong(-1); - // optional attributes to report to datadog - /* The type of the span (web, db, etc). See DDSpanTypes. */ - private final String type = null; - /* Marks the span as having an error. */ - private final boolean isErrored = false; - /* Additional key-value pairs for a span. */ - private final Map meta = null; +import lombok.extern.slf4j.Slf4j; - /** - * Create a span with a start time of the current timestamp. - * - * @param trace The trace to associate this span with - * @param parentContext identifies the parent of this span. May be null. - * @param clock The clock to use to measure the span's duration. - * @param interceptors interceptors to run on the span +/** Concrete implementation of a span */ +@Slf4j +class SpanImpl implements Span { + + private final TraceInternal trace; + + private final SpanContext context; + private final Timestamp startTimestamp; + + /* Note: some fields are volatile so we could make getters non synchronized. + Alternatively we could make getters synchronized, but this may create more contention. */ - SpanImpl( - final TraceImpl trace, - final SpanContext parentContext, - final Clock clock, - List interceptors) {} + private volatile Long duration = null; + + private volatile String service; + private volatile String resource; + private volatile String type; + private volatile String name; + private volatile boolean errored = false; + + private final Map meta = new HashMap<>(); + + private final List interceptors; /** - * Create a span with the a specific start timestamp. + * Create a span with the a specific startTimestamp timestamp. * - * @param trace The trace to associate this span with + * @param trace The trace to associate this span with. * @param parentContext identifies the parent of this span. May be null. - * @param clock The clock to use to measure the span's duration. - * @param interceptors interceptors to run on the span - * @param startTimestampNanoseconds Epoch time in nanoseconds when this span started. + * @param startTimestamp timestamp when this span was started. */ SpanImpl( - final TraceImpl trace, - final SpanContext parentContext, - final Clock clock, - List interceptors, - final long startTimestampNanoseconds) {} + final TraceInternal trace, final SpanContext parentContext, final Timestamp startTimestamp) { + this.trace = trace; + + context = SpanContextImpl.fromParent(parentContext); + + if (startTimestamp == null) { + reportUsageError("Cannot create span without timestamp: %s", trace); + throw new TraceException(String.format("Cannot create span without timestamp: %s", trace)); + } + this.startTimestamp = startTimestamp; + service = trace.getTracer().getDefaultServiceName(); + interceptors = trace.getTracer().getInterceptors(); + + for (final Interceptor interceptor : interceptors) { + interceptor.afterSpanStarted(this); + } + } @Override public Trace getTrace() { - return null; + return trace; } @Override - public void finish() {} + public SpanContext getContext() { + return context; + } @Override - public void finish(long finishTimestampNanoseconds) {} + public Timestamp getStartTimestamp() { + return startTimestamp; + } @Override - public boolean isFinished() { - return false; + public Long getDuration() { + return duration; } @Override - public void attachThrowable(Throwable t) {} + public boolean isFinished() { + return duration != null; + } @Override - public void setError(boolean isErrored) {} + public String getService() { + return service; + } @Override - public SpanContext getContext() { - return null; + public synchronized void setService(final String service) { + if (isFinished()) { + reportSetterUsageError("service"); + } else { + this.service = service; + } } @Override - public Object getMeta(String key) { - return null; + public String getResource() { + return resource; } @Override - public void setMeta(String key, String value) {} + public synchronized void setResource(final String resource) { + if (isFinished()) { + reportSetterUsageError("resource"); + } else { + this.resource = resource; + } + } @Override - public void setMeta(String key, boolean value) {} + public String getType() { + return type; + } @Override - public void setMeta(String key, Number value) {} + public synchronized void setType(final String type) { + if (isFinished()) { + reportSetterUsageError("type"); + } else { + this.type = type; + } + } @Override public String getName() { - return null; + return name; } @Override - public void setName(String newName) {} + public synchronized void setName(final String name) { + if (isFinished()) { + reportSetterUsageError("name"); + } else { + this.name = name; + } + } @Override - public String getResource() { - return null; + public boolean isErrored() { + return errored; } @Override - public void setResource(String newResource) {} + public synchronized void attachThrowable(final Throwable throwable) { + if (isFinished()) { + reportSetterUsageError("throwable"); + } else { + setErrored(true); + + setMeta(DDTags.ERROR_MSG, throwable.getMessage()); + setMeta(DDTags.ERROR_TYPE, throwable.getClass().getName()); + + final StringWriter errorString = new StringWriter(); + throwable.printStackTrace(new PrintWriter(errorString)); + setMeta(DDTags.ERROR_STACK, errorString.toString()); + } + } @Override - public String getService() { - return null; + public synchronized void setErrored(final boolean errored) { + if (isFinished()) { + reportSetterUsageError("errored"); + } else { + this.errored = errored; + } } @Override - public void setService(String newService) {} + public synchronized Object getMeta(final String key) { + return meta.get(key); + } + + protected synchronized void setMeta(final String key, final Object value) { + if (isFinished()) { + reportSetterUsageError("meta value " + key); + } else { + if (value == null) { + meta.remove(key); + } else { + meta.put(key, value); + } + } + } @Override - public String getType() { - return null; + public void setMeta(final String key, final String value) { + setMeta(key, (Object) value); } @Override - public void setType(String newType) {} + public void setMeta(final String key, final Boolean value) { + setMeta(key, (Object) value); + } @Override - public boolean isErrored() { - return false; + public void setMeta(final String key, final Number value) { + setMeta(key, (Object) value); + } + + @Override + public synchronized void finish() { + if (isFinished()) { + reportUsageError("Attempted to finish span that is already finished: %s", this); + } else { + finishSpan(startTimestamp.getDuration(), false); + } + } + + @Override + public synchronized void finish(final long finishTimestampNanoseconds) { + if (isFinished()) { + reportUsageError("Attempted to finish span that is already finish: %s", this); + } else { + finishSpan(startTimestamp.getDuration(finishTimestampNanoseconds), false); + } + } + + @Override + protected synchronized void finalize() { + try { + // Note: according to docs finalize is only called once for a given instance - even if + // instance is 'revived' from the dead by passing reference to some other object and + // then dies again. + if (!isFinished()) { + trace + .getTracer() + .reportWarning( + "Finishing span due to GC, this will prevent trace from being reported: %s", this); + finishSpan(startTimestamp.getDuration(), true); + } + } catch (final Throwable t) { + // Exceptions thrown in finalizer are eaten up and ignored, so log them instead + log.debug("Span finalizer had thrown an exception: ", t); + } + } + + /** + * Helper method to perform operations to finish the span. + * + *

    Note: This has to be called under object lock. + * + * @param duration duration of the span. + * @param fromGC true iff we are closing span because it is being GCed, this will make trace + * invalid. + */ + private void finishSpan(final long duration, final boolean fromGC) { + // Run interceptors in 'reverse' order + for (int i = interceptors.size() - 1; i >= 0; i--) { + interceptors.get(i).beforeSpanFinished(this); + } + this.duration = duration; + trace.finishSpan(this, fromGC); + } + + private void reportUsageError(final String message, final Object... args) { + trace.getTracer().reportError(message, args); + } + + private void reportSetterUsageError(final String fieldName) { + reportUsageError("Attempted to set '%s' when span is already finished: %s", fieldName, this); } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Timestamp.java b/dd-trace/src/main/java/datadog/trace/tracer/Timestamp.java new file mode 100644 index 00000000000..c4e4963fe2d --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/Timestamp.java @@ -0,0 +1,80 @@ +package datadog.trace.tracer; + +import static java.lang.Math.max; + +import lombok.EqualsAndHashCode; + +/** + * Class that encapsulations notion of a given timestamp, or instant in time. + * + *

    Timestamps are created by a [@link Clock} instance. + */ +@EqualsAndHashCode +public class Timestamp { + + private final Clock clock; + private final long nanoTicks; + + /** + * Create timestamp for a given clock and given nanoTicks state + * + * @param clock clock instance + */ + Timestamp(final Clock clock) { + this.clock = clock; + nanoTicks = clock.nanoTicks(); + } + + /** @return clock instance used by this timestamp */ + public Clock getClock() { + return clock; + } + + /** @return duration in nanoseconds from this time stamp to current time. */ + public long getDuration() { + return getDuration(new Timestamp(clock)); + } + + /** + * Get duration in nanoseconds from this time stamp to provided finish timestamp. + * + * @param finishTimestamp finish timestamp to use as period's end. + * @return duration in nanoseconds. + */ + public long getDuration(final Timestamp finishTimestamp) { + if (clock != finishTimestamp.clock) { + clock + .getTracer() + .reportError( + "Trying to find duration between two timestamps created by different clocks. Current clock: %s, finish timestamp clock: %s", + clock, finishTimestamp.clock); + // Do our best to try to calculate nano-second time using millisecond clock start time and + // nanosecond offset. + return max( + 0, + (finishTimestamp.clock.getStartTimeNano() + finishTimestamp.startTicksOffset()) + - (clock.getStartTimeNano() + startTicksOffset())); + } + return max(0, finishTimestamp.nanoTicks - nanoTicks); + } + + /** + * Duration in nanoseconds for external finish time. + * + *

    Note: since we can only get time with millisecond precision in Java this ends up being + * effectively millisecond precision duration converted to nanoseconds. + * + * @param finishTimeNanoseconds + * @return duration in nanoseconds (with millisecond precision). + */ + public long getDuration(final long finishTimeNanoseconds) { + // This is calculated as the difference between finish time and clock start time and then + // subtracting difference between timestamp nanoticks and clock start nanoticks to account for + // time after clock has been created and before timestamp has been created. + return max(0, finishTimeNanoseconds - clock.getStartTimeNano() - startTicksOffset()); + } + + private long startTicksOffset() { + return nanoTicks - clock.getStartNanoTicks(); + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Trace.java b/dd-trace/src/main/java/datadog/trace/tracer/Trace.java index 0137fdb8b5f..0fe5c1eb5f1 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/Trace.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/Trace.java @@ -1,5 +1,7 @@ package datadog.trace.tracer; +import java.util.List; + /** * A tree of {@link Span}s with a single root node plus logic to determine when to report said tree * to the backend. @@ -7,23 +9,44 @@ *

    A trace will be written when all of its spans are finished and all trace continuations are * closed. * - *

    To create a Trace, see {@link Tracer#buildTrace()} + *

    To create a Trace, see {@link Tracer#buildTrace(SpanContext parentContext)} */ public interface Trace { - /** Get the tracer which created this trace. */ + /** @return the tracer which created this trace. */ Tracer getTracer(); - /** Get the root span for this trace. This will never be null. */ + /** @return the root span for this trace. This will never be null. */ Span getRootSpan(); /** - * Create a new span in this trace as a child of the given parentSpan. + * @return list of spans for this trace. Note: if trace is not finished this will report error. + */ + List getSpans(); + + /** @return true iff trace is valid (invalid traces should not be reported). */ + boolean isValid(); + + /** @return current timestamp using this trace's clock */ + Timestamp createCurrentTimestamp(); + + /** + * Create a new span in this trace as a child of the given parent context. * - * @param parentSpan the parent to use. Must be a span in this trace. + * @param parentContext the parent to use. Must be a span in this trace. * @return the new span. It is the caller's responsibility to ensure {@link Span#finish()} is * eventually invoked on this span. */ - Span createSpan(Span parentSpan); + Span createSpan(final SpanContext parentContext); + + /** + * Create a new span in this trace as a child of the given parent context. + * + * @param parentContext the parent to use. Must be a span in this trace. + * @param startTimestamp timestamp to use as start timestamp for a new span. + * @return the new span. It is the caller's responsibility to ensure {@link Span#finish()} is + * eventually invoked on this span. + */ + Span createSpan(final SpanContext parentContext, final Timestamp startTimestamp); /** * Create a new continuation for this trace @@ -33,27 +56,4 @@ public interface Trace { * Continuation#close()} is eventually invoked on this continuation. */ Continuation createContinuation(Span parentSpan); - - interface Interceptor { - /** - * Invoked when a trace is eligible for writing but hasn't been handed off to its writer yet. - * - * @param trace The intercepted trace. - */ - void beforeTraceWritten(Trace trace); - } - - /** A way to prevent a trace from reporting without creating a span. */ - interface Continuation { - /** - * Close the continuation. Continuation's trace will not block reporting on account of this - * continuation. - * - *

    Has no effect after the first invocation. - */ - void close(); - - // TODO: doc - Span span(); - } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/TraceException.java b/dd-trace/src/main/java/datadog/trace/tracer/TraceException.java new file mode 100644 index 00000000000..f2cb0a1789b --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/TraceException.java @@ -0,0 +1,54 @@ +package datadog.trace.tracer; + +/** Tracer-specific runtime exception. */ +public class TraceException extends RuntimeException { + + /** + * Constructs a new trace exception with {@code null} as its detail message. The cause is not + * initialized, and may subsequently be initialized by a call to {@link #initCause}. + */ + public TraceException() { + super(); + } + + /** + * Constructs a new trace exception with the specified detail message. The cause is not + * initialized, and may subsequently be initialized by a call to {@link #initCause}. + * + * @param message the detail message. The detail message is saved for later retrieval by the + * {@link #getMessage()} method. + */ + public TraceException(final String message) { + super(message); + } + + /** + * Constructs a new trace exception with the specified detail message and cause. + * + *

    Note that the detail message associated with {@code cause} is not automatically + * incorporated in this runtime exception's detail message. + * + * @param message the detail message (which is saved for later retrieval by the {@link + * #getMessage()} method). + * @param cause the cause (which is saved for later retrieval by the {@link #getCause()} method). + * (A null value is permitted, and indicates that the cause is nonexistent or + * unknown.) + */ + public TraceException(final String message, final Throwable cause) { + super(message, cause); + } + + /** + * Constructs a new runtime exception with the specified cause and a detail message of + * (cause==null ? null : cause.toString()) (which typically contains the class and detail + * message of cause). This constructor is useful for runtime exceptions that are little + * more than wrappers for other throwables. + * + * @param cause the cause (which is saved for later retrieval by the {@link #getCause()} method). + * (A null value is permitted, and indicates that the cause is nonexistent or + * unknown.) + */ + public TraceException(final Throwable cause) { + super(cause); + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/TraceImpl.java b/dd-trace/src/main/java/datadog/trace/tracer/TraceImpl.java index 766a51fa95a..44b4b8ef24e 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/TraceImpl.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/TraceImpl.java @@ -1,23 +1,36 @@ package datadog.trace.tracer; import datadog.trace.tracer.writer.Writer; -import java.lang.ref.WeakReference; +import java.util.ArrayList; +import java.util.Collections; import java.util.List; import java.util.Set; +import java.util.WeakHashMap; -public class TraceImpl implements Trace { - private final Writer writer = null; +class TraceImpl implements TraceInternal { - // TODO: Document approach to weak-referencdes and cleanup. If a span has to be closed by our GC - // logic the trace should increment the writer's count but not report (invalid api usage produces - // suspect data). - private final Set> inFlightSpans = null; - private final Set> inFlightContinuations = null; + /* We use weakly referenced sets to track 'in-flight' spans and continuations. We use span/continuation's + finalizer to notify trace that span/continuation is being GCed. + If any part of the trace (span or continuation) has been was finished (closed) via GC then trace would be + marked as 'invalid' and will not be reported the the backend. Instead only writer's counter would be incremented. + This allows us not to report traces that have wrong timing information. + Note: instead of using {@link WeakHashMap} we may want to consider using more fancy implementations from + {@link datadog.trace.agent.tooling.WeakMapSuppliers}. If we do this care should be taken to avoid creating + cleanup threads per trace. + */ + private final Set inFlightSpans = + Collections.newSetFromMap(new WeakHashMap()); + private final Set inFlightContinuations = + Collections.newSetFromMap(new WeakHashMap()); /** Strong refs to spans which are closed */ - private final List finishedSpans = null; + private final List finishedSpans = new ArrayList(); - private final Span rootSpan = null; + private final Tracer tracer; + private final Clock clock; + private final Span rootSpan; + private boolean valid = true; + private boolean finished = false; /** * Create a new Trace. @@ -25,30 +38,160 @@ public class TraceImpl implements Trace { * @param tracer the Tracer to apply settings from. */ TraceImpl( - Tracer tracer, - SpanContext rootSpanParentContext, - final long rootSpanStartTimestampNanoseconds) {} + final Tracer tracer, + final SpanContext rootSpanParentContext, + final Timestamp rootSpanStartTimestamp) { + this.tracer = tracer; + clock = rootSpanStartTimestamp.getClock(); + rootSpan = new SpanImpl(this, rootSpanParentContext, rootSpanStartTimestamp); + inFlightSpans.add(rootSpan); + } @Override public Tracer getTracer() { - return null; + return tracer; } @Override public Span getRootSpan() { - return null; + return rootSpan; + } + + @Override + public synchronized List getSpans() { + if (!finished) { + tracer.reportError("Cannot get spans, trace is not finished yet: %s", this); + return Collections.EMPTY_LIST; + } + return Collections.unmodifiableList(finishedSpans); + } + + @Override + public synchronized boolean isValid() { + return valid; + } + + @Override + public Timestamp createCurrentTimestamp() { + return clock.createCurrentTimestamp(); + } + + @Override + public Span createSpan(final SpanContext parentContext) { + return createSpan(parentContext, createCurrentTimestamp()); } @Override - public Span createSpan(Span parentSpan) { - return null; + public synchronized Span createSpan( + final SpanContext parentContext, final Timestamp startTimestamp) { + checkTraceFinished("create span"); + if (parentContext == null) { + throw new TraceException("Got null parent context, trace: " + this); + } + if (!parentContext.getTraceId().equals(rootSpan.getContext().getTraceId())) { + throw new TraceException( + String.format( + "Wrong trace id when creating a span. Got %s, expected %s", + parentContext.getTraceId(), rootSpan.getContext().getTraceId())); + } + final Span span = new SpanImpl(this, parentContext, startTimestamp); + inFlightSpans.add(span); + return span; } @Override - public Continuation createContinuation(Span parentSpan) { - return null; + public synchronized Continuation createContinuation(final Span span) { + checkTraceFinished("create continuation"); + if (span == null) { + throw new TraceException("Got null parent span, trace: " + this); + } + if (!span.getContext().getTraceId().equals(rootSpan.getContext().getTraceId())) { + throw new TraceException( + String.format( + "Wrong trace id when creating a span. Got %s, expected %s", + span.getContext().getTraceId(), rootSpan.getContext().getTraceId())); + } + final Continuation continuation = new ContinuationImpl(this, span); + inFlightContinuations.add(continuation); + return continuation; } - // TODO methods to inform the trace that continuations and spans finished/closed. Also be able to - // inform trace when a span finishes due to GC. + @Override + public synchronized void finishSpan(final Span span, final boolean invalid) { + checkTraceFinished("finish span"); + if (!inFlightSpans.contains(span)) { + tracer.reportError("Trace doesn't contain continuation to finish: %s, trace: %s", span, this); + return; + } + if (invalid) { + valid = false; + } + inFlightSpans.remove(span); + finishedSpans.add(span); + checkAndWriteTrace(); + } + + @Override + public synchronized void closeContinuation( + final Continuation continuation, final boolean invalid) { + checkTraceFinished("close continuation"); + if (!inFlightContinuations.contains(continuation)) { + tracer.reportError( + "Trace doesn't contain continuation to finish: %s, trace: %s", continuation, this); + return; + } + if (invalid) { + valid = false; + } + inFlightContinuations.remove(continuation); + checkAndWriteTrace(); + } + + /** + * Helper to check if trace is ready to be written and write it if it is. + * + *

    Note: This has to be called under object lock. + */ + private void checkAndWriteTrace() { + if (inFlightSpans.isEmpty() && inFlightContinuations.isEmpty()) { + final Writer writer = tracer.getWriter(); + writer.incrementTraceCount(); + final Trace trace = runInterceptorsBeforeTraceWritten(this); + if (trace != null && tracer.getSampler().sample(trace)) { + writer.write(trace); + } + finished = true; + } + } + + /** + * Helper to run interceptor hooks before trace is finished. + * + *

    Note: This has to be called under object lock. + */ + private Trace runInterceptorsBeforeTraceWritten(Trace trace) { + final List interceptors = tracer.getInterceptors(); + // Run interceptors in 'reverse' order + for (int i = interceptors.size() - 1; i >= 0; i--) { + // TODO: we probably should handle exceptions in interceptors more or less gracefully + trace = interceptors.get(i).beforeTraceWritten(trace); + if (trace == null) { + break; + } + } + return trace; + } + + /** + * Helper to check if trace is finished and report an error if it is. + * + *

    This has to be called under object lock + * + * @param action action to report error with. + */ + private void checkTraceFinished(final String action) { + if (finished) { + tracer.reportError("Cannot %s, trace has already been finished: %s", action, this); + } + } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/TraceInternal.java b/dd-trace/src/main/java/datadog/trace/tracer/TraceInternal.java new file mode 100644 index 00000000000..ab0b694748b --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/TraceInternal.java @@ -0,0 +1,21 @@ +package datadog.trace.tracer; + +/** Trace interface that provides additional methods used internally */ +interface TraceInternal extends Trace { + + /** + * Called by the span to inform trace that span is finished. + * + * @param span span to finish. + * @param invalid true iff span is 'invalid'. + */ + void finishSpan(final Span span, final boolean invalid); + + /** + * Called by the continuation to inform trace that span is closed. + * + * @param continuation continuation to close. + * @param invalid true iff span is 'invalid'. + */ + void closeContinuation(final Continuation continuation, final boolean invalid); +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/Tracer.java b/dd-trace/src/main/java/datadog/trace/tracer/Tracer.java index 0eeb0d05536..5f8ef361d27 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/Tracer.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/Tracer.java @@ -1,40 +1,110 @@ package datadog.trace.tracer; import datadog.trace.api.Config; +import datadog.trace.tracer.sampling.AllSampler; import datadog.trace.tracer.sampling.Sampler; +import datadog.trace.tracer.writer.LoggingWriter; import datadog.trace.tracer.writer.Writer; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import lombok.extern.slf4j.Slf4j; /** A Tracer creates {@link Trace}s and holds common settings across traces. */ +@Slf4j public class Tracer { - /** Default service name if none provided on the trace or span */ - private final String defaultServiceName = null; + /** Writer is an charge of reporting traces and spans to the desired endpoint */ - private final Writer writer = null; + private final Writer writer; /** Sampler defines the sampling policy in order to reduce the number of traces for instance */ - private final Sampler sampler = null; + private final Sampler sampler; /** Settings for this tracer. */ - private final Config config = null; - /** The clock to use for tracing. */ - private final Clock clock = null; + private final Config config; + + /** Interceptors to be called on certain trace and span events */ + private final List interceptors; + + public Tracer() { + this(Config.get()); + } + + public Tracer(final List interceptors) { + this(Config.get(), interceptors); + } + + public Tracer(final Config config) { + this(config, Collections.emptyList()); + } + + public Tracer(final Config config, final List interceptors) { + // TODO: implement and include "standard" interceptors + this( + config, + new LoggingWriter(), + new AllSampler(), + Collections.unmodifiableList(new ArrayList<>(interceptors))); + } + + Tracer( + final Config config, + final Writer writer, + final Sampler sampler, + final List interceptors) { + this.config = config; + // TODO: we probably need to implement some sort of 'close' method for Tracer + this.writer = writer; + this.sampler = sampler; + this.interceptors = Collections.unmodifiableList(new ArrayList<>(interceptors)); + } + + /** @return {@link Writer} used by this tracer */ + public Writer getWriter() { + return writer; + } + + /** @return {@link Sampler} used by this tracer. */ + public Sampler getSampler() { + return sampler; + } + + /** @return unmodifiable list of trace/span interceptors. */ + public List getInterceptors() { + return interceptors; + } + + /** @return service name to use on span by default. */ + String getDefaultServiceName() { + return config.getServiceName(); + } + + /** + * @return timestamp for current time. Note: this is mainly useful when there is no 'current' + * trace. If there is 'current' trace already then one should use it to get timestamps. + */ + public Timestamp createCurrentTimestamp() { + return new Clock(this).createCurrentTimestamp(); + } /** * Construct a new trace using this tracer's settings and return the root span. * + * @param parentContext parent context of a root span in this trace. May be null. * @return The root span of the new trace. */ public Span buildTrace(final SpanContext parentContext) { - return null; + return buildTrace(parentContext, createCurrentTimestamp()); } /** * Construct a new trace using this tracer's settings and return the root span. * - * @param rootSpanStartTimestampNanoseconds Epoch time in nanoseconds when the root span started. + * @param parentContext parent context of a root span in this trace. May be null. + * @param timestamp root span start timestamp. * @return The root span of the new trace. */ - public Span buildTrace( - final SpanContext parentContext, final long rootSpanStartTimestampNanoseconds) { - return null; + public Span buildTrace(final SpanContext parentContext, final Timestamp timestamp) { + final Trace trace = new TraceImpl(this, parentContext, timestamp); + return trace.getRootSpan(); } // TODO: doc inject and extract @@ -44,4 +114,25 @@ public void inject(final SpanContext spanContext, final Object format, final public SpanContext extract(final Object format, final T carrier) { return null; } + + // TODO: we can move these two into a separate class and move all '*Impl' and '*Internal' classes + // into separate package + // TODO: provide some sort of ratelimiting here to avoid filling up disk space. + /* + Report warning to the log/console. This never throws exception + */ + void reportWarning(final String message, final Object... args) { + final String completeMessage = String.format(message, args); + log.debug(completeMessage); + } + + /* + Report error to the log/console. This may throw an exception + */ + void reportError(final String message, final Object... args) { + // TODO: Provide way to do logging or throwing an exception according to config? + final String completeMessage = String.format(message, args); + log.debug(completeMessage); + throw new TraceException(completeMessage); + } } diff --git a/dd-trace/src/main/java/datadog/trace/tracer/sampling/AllSampler.java b/dd-trace/src/main/java/datadog/trace/tracer/sampling/AllSampler.java new file mode 100644 index 00000000000..2c1153551ce --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/sampling/AllSampler.java @@ -0,0 +1,11 @@ +package datadog.trace.tracer.sampling; + +import datadog.trace.tracer.Trace; + +/** Sampler that samples all traces. */ +public class AllSampler implements Sampler { + @Override + public boolean sample(final Trace trace) { + return true; + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/writer/LoggingWriter.java b/dd-trace/src/main/java/datadog/trace/tracer/writer/LoggingWriter.java new file mode 100644 index 00000000000..b7adb218024 --- /dev/null +++ b/dd-trace/src/main/java/datadog/trace/tracer/writer/LoggingWriter.java @@ -0,0 +1,29 @@ +package datadog.trace.tracer.writer; + +import datadog.trace.tracer.Trace; +import lombok.extern.slf4j.Slf4j; + +/** Writer implementation that just logs traces as they are being written */ +@Slf4j +public class LoggingWriter implements Writer { + @Override + public void write(final Trace trace) { + log.debug("Trace written: {}", trace); + } + + @Override + public void incrementTraceCount() { + // Nothing to do here. + } + + @Override + public void start() { + // TODO: do we really need this? and if we do - who is responsible for calling this? + log.debug("{} started", getClass().getSimpleName()); + } + + @Override + public void close() { + log.debug("{} closed", getClass().getSimpleName()); + } +} diff --git a/dd-trace/src/main/java/datadog/trace/tracer/writer/Writer.java b/dd-trace/src/main/java/datadog/trace/tracer/writer/Writer.java index b10ded67914..1dc07cab7e8 100644 --- a/dd-trace/src/main/java/datadog/trace/tracer/writer/Writer.java +++ b/dd-trace/src/main/java/datadog/trace/tracer/writer/Writer.java @@ -4,8 +4,13 @@ /** A writer sends traces to some place. */ public interface Writer { + /** - * Write a trace represented by the entire list of all the finished spans + * Write a trace represented by the entire list of all the finished spans. + * + *

    It is up to the tracer to decide if the trace should be written (e.g. for invalid traces). + * + *

    This call doesn't increment trace counter, see {@code incrementTraceCount} for that * * @param trace the trace to write */ diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/ClockTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/ClockTest.groovy new file mode 100644 index 00000000000..7c4fcf16393 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/ClockTest.groovy @@ -0,0 +1,53 @@ +package datadog.trace.tracer + +import nl.jqno.equalsverifier.EqualsVerifier +import nl.jqno.equalsverifier.Warning +import spock.lang.Shared +import spock.lang.Specification + +import java.util.concurrent.TimeUnit + +class ClockTest extends Specification { + + // Assume it takes less than a minute to run this test + public static final long MINUTE = TimeUnit.MINUTES.toNanos(1) + + @Shared + def tracer = Mock(Tracer) + + def "test getters"() { + setup: + def currentTimeNano = TimeUnit.MILLISECONDS.toNanos(System.currentTimeMillis()) + def nanoTicks = System.nanoTime() + + when: + def clock = new Clock(tracer) + + then: + clock.getTracer() == tracer + clock.getStartTimeNano() - currentTimeNano <= MINUTE + clock.getStartNanoTicks() - nanoTicks <= MINUTE + clock.epochTimeNano() - currentTimeNano <= MINUTE + TimeUnit.MICROSECONDS.toNanos(clock.epochTimeMicro()) - currentTimeNano <= MINUTE + clock.nanoTicks() - nanoTicks <= MINUTE + } + + def "test timestamp creation"() { + setup: + def clock = new Clock(tracer) + + when: + def timestamp = clock.createCurrentTimestamp() + + then: + timestamp.getClock() == clock + } + + def "test equals"() { + when: + EqualsVerifier.forClass(Clock).suppress(Warning.STRICT_INHERITANCE).verify() + + then: + noExceptionThrown() + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/ContinuationImplTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/ContinuationImplTest.groovy new file mode 100644 index 00000000000..e32988d4206 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/ContinuationImplTest.groovy @@ -0,0 +1,105 @@ +package datadog.trace.tracer + + +import spock.lang.Specification + +class ContinuationImplTest extends Specification { + + def tracer = Mock(Tracer) + def trace = Mock(TraceImpl) { + getTracer() >> tracer + } + def span = Mock(Span) + + def "test getters"() { + when: + def continuation = new ContinuationImpl(trace, span) + + then: + continuation.getTrace() == trace + continuation.getSpan() == span + } + + def "happy lifecycle"() { + when: "continuation is created" + def continuation = new ContinuationImpl(trace, span) + + then: "continuation is opened" + !continuation.isClosed() + + when: "close continuation" + continuation.close() + + then: "continuation is closed and no errors are reported" + continuation.isClosed() + 0 * tracer.reportError(*_) + and: "continuation is reported as closed to a trace" + 1 * trace.closeContinuation(continuation, false) + + when: "continuation is finalized" + continuation.finalize() + + then: "continuation is still closed and no errors are reported" + continuation.isClosed() + 0 * tracer.reportError(*_) + and: "continuation is not reported as closed to a trace again" + 0 * trace.closeContinuation(_, _) + } + + def "double close"() { + setup: + def continuation = new ContinuationImpl(trace, span) + + when: "close continuation" + continuation.close() + + then: "continuation is closed" + continuation.isClosed() + + when: "close continuation again" + continuation.close() + + then: "error is reported" + 1 * tracer.reportError(_, [continuation]) + and: "continuation is not reported as closed to a trace again" + 0 * trace.closeContinuation(_, _) + } + + def "finalize"() { + setup: + def continuation = new ContinuationImpl(trace, span) + + when: "finalize continuation" + continuation.finalize() + + then: "continuation is closed" + continuation.isClosed() + and: "continuation is reported as closed to a trace" + 1 * trace.closeContinuation(continuation, true) + and: "warning is reported" + 1 * tracer.reportWarning(_, [continuation]) + + when: "finalize continuation again" + continuation.finalize() + + then: "continuation is still closed" + continuation.isClosed() + and: "continuation is not reported as closed to a trace again" + 0 * trace.closeContinuation(_, _) + and: "no error is reported" + 0 * tracer.reportError(_, *_) + } + + def "finalize catches all exceptions"() { + setup: + def continuation = new ContinuationImpl(trace, span) + + when: + continuation.finalize() + + then: + 1 * trace.getTracer() >> { throw new Throwable() } + noExceptionThrown() + } + +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/SpanContextImplTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/SpanContextImplTest.groovy new file mode 100644 index 00000000000..01599734b16 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/SpanContextImplTest.groovy @@ -0,0 +1,54 @@ +package datadog.trace.tracer + +import datadog.trace.api.sampling.PrioritySampling +import nl.jqno.equalsverifier.EqualsVerifier +import nl.jqno.equalsverifier.Warning +import spock.lang.Specification + + +class SpanContextImplTest extends Specification { + + def "test getters"() { + when: + def context = new SpanContextImpl("trace id", "parent id", "span id") + + then: + context.getTraceId() == "trace id" + context.getParentId() == "parent id" + context.getSpanId() == "span id" + + // TODO: this still to be implemented + context.getSamplingFlags() == PrioritySampling.SAMPLER_KEEP + } + + def "create from parent"() { + setup: + def parent = new SpanContextImpl("trace id", "parent's parent id", "parent span id") + + when: + def context = SpanContextImpl.fromParent(parent) + + then: + context.getTraceId() == "trace id" + context.getParentId() == "parent span id" + context.getSpanId() ==~ /\d+/ + } + + def "create from no parent"() { + when: + def context = SpanContextImpl.fromParent(null) + + then: + context.getTraceId() ==~ /\d+/ + context.getParentId() == SpanContextImpl.ZERO + context.getSpanId() ==~ /\d+/ + } + + def "test equals"() { + when: + EqualsVerifier.forClass(SpanContextImpl).suppress(Warning.STRICT_INHERITANCE).verify() + + then: + noExceptionThrown() + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/SpanImplTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/SpanImplTest.groovy new file mode 100644 index 00000000000..aad66720667 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/SpanImplTest.groovy @@ -0,0 +1,292 @@ +package datadog.trace.tracer + +import datadog.trace.api.DDTags +import spock.lang.Specification + +class SpanImplTest extends Specification { + + private static final String SERVICE_NAME = "service.name" + private static final String PARENT_TRACE_ID = "trace id" + private static final String PARENT_SPAN_ID = "span id" + private static final long DURATION = 321 + + def interceptors = [Mock(name: "interceptor-1", Interceptor), Mock(name: "interceptor-2", Interceptor)] + def tracer = Mock(Tracer) { + getDefaultServiceName() >> SERVICE_NAME + getInterceptors() >> interceptors + } + def parentContext = Mock(SpanContextImpl) { + getTraceId() >> PARENT_TRACE_ID + getSpanId() >> PARENT_SPAN_ID + } + def startTimestamp = Mock(Timestamp) { + getDuration() >> DURATION + getDuration(_) >> { args -> args[0] + DURATION } + } + def trace = Mock(TraceImpl) { + getTracer() >> tracer + } + + def "test setters and default values"() { + when: "create span" + def span = new SpanImpl(trace, parentContext, startTimestamp) + + then: "span got created" + span.getTrace() == trace + span.getStartTimestamp() == startTimestamp + span.getDuration() == null + span.getContext().getTraceId() == PARENT_TRACE_ID + span.getContext().getParentId() == PARENT_SPAN_ID + span.getContext().getSpanId() ==~ /\d+/ + span.getService() == SERVICE_NAME + span.getResource() == null + span.getType() == null + span.getName() == null + !span.isErrored() + + when: "span settings changes" + span.setService("new.service.name") + span.setResource("resource") + span.setType("type") + span.setName("name") + span.setErrored(true) + + then: "span fields get updated" + span.getService() == "new.service.name" + span.getResource() == "resource" + span.getType() == "type" + span.getName() == "name" + span.isErrored() + } + + def "test setter #setter on finished span"() { + setup: "create span" + def span = new SpanImpl(trace, parentContext, startTimestamp) + span.finish() + + when: "call setter on finished span" + span."$setter"(newValue) + + then: "error reported" + 1 * tracer.reportError(_, { + it[0] == fieldName + it[1] == span + }) + and: "value unchanged" + span."$getter"() == oldValue + + where: + fieldName | setter | getter | newValue | oldValue + "service" | "setService" | "getService" | "new service" | SERVICE_NAME + "resource" | "setResource" | "getResource" | "new resource" | null + "type" | "setType" | "getType" | "new type" | null + "name" | "setName" | "getName" | "new name" | null + "errored" | "setErrored" | "isErrored" | true | false + } + + def "test meta set and remove for #key"() { + when: + def span = new SpanImpl(trace, parentContext, startTimestamp) + + then: + span.getMeta(key) == null + + when: + span.setMeta(key, value) + + then: + span.getMeta(key) == value + + when: + span.setMeta(key, value.class.cast(null)) + + then: + span.getMeta(key) == null + + where: + key | value + "string.key" | "string" + "boolean.key" | true + "number.key" | 123 + } + + def "test meta setter on finished span for #key"() { + setup: "create span" + def span = new SpanImpl(trace, parentContext, startTimestamp) + span.finish() + + when: "call setter on finished span" + span.setMeta(key, value) + + then: "error reported" + 1 * tracer.reportError(_, { + it[0] == "meta value " + key + it[1] == span + }) + and: "value unchanged" + span.getMeta(key) == null + + where: + key | value + "string.key" | "string" + "boolean.key" | true + "number.key" | 123 + } + + def "test attachThrowable"() { + setup: + def exception = new RuntimeException("test message") + when: + def span = new SpanImpl(trace, parentContext, startTimestamp) + + then: + !span.isErrored() + span.getMeta(DDTags.ERROR_MSG) == null + span.getMeta(DDTags.ERROR_TYPE) == null + span.getMeta(DDTags.ERROR_STACK) == null + + when: + span.attachThrowable(exception) + + then: + span.isErrored() + span.getMeta(DDTags.ERROR_MSG) == "test message" + span.getMeta(DDTags.ERROR_TYPE) == RuntimeException.getName() + span.getMeta(DDTags.ERROR_STACK) != null + } + + def "test attachThrowable on finished span"() { + setup: "create span" + def exception = new RuntimeException("test message") + def span = new SpanImpl(trace, parentContext, startTimestamp) + span.finish() + + when: "attach throwable" + span.attachThrowable(exception) + + then: "error reported" + 1 * tracer.reportError(_, { + it[0] == "throwable" + it[1] == span + }) + and: "span unchanged" + !span.isErrored() + span.getMeta(DDTags.ERROR_MSG) == null + span.getMeta(DDTags.ERROR_TYPE) == null + span.getMeta(DDTags.ERROR_STACK) == null + } + + def "test no parent"() { + when: + def span = new SpanImpl(trace, null, startTimestamp) + + then: + span.getContext().getTraceId() ==~ /\d+/ + span.getContext().getParentId() == SpanContextImpl.ZERO + span.getContext().getSpanId() ==~ /\d+/ + } + + def "test lifecycle '#name'"() { + when: "create span" + def span = new SpanImpl(trace, parentContext, startTimestamp) + + then: "interceptors called" + interceptors.each({ interceptor -> + then: + 1 * interceptor.afterSpanStarted({ + // Apparently invocation verification has to know expected value before 'when' section + // To work around this we just check parent span id + it.getContext().getParentId() == parentContext.getSpanId() + }) + 0 * interceptor._ + }) + then: + !span.isFinished() + + when: "finish/finalize span" + span."$method"(*methodArgs) + + then: "warning is reported" + _ * trace.getTracer() >> tracer + if (finalizeErrorReported) { + 1 * tracer.reportWarning(_, span) + } + then: "interceptors called" + interceptors.reverseEach({ interceptor -> + then: + 1 * interceptor.beforeSpanFinished({ + it == span + it.getDuration() == null // Make sure duration is not set yet + }) + 0 * interceptor._ + }) + then: "trace is informed that span is closed" + 1 * trace.finishSpan({ + it == span + it.getDuration() == expectedDuration + }, finalizeErrorReported) + 0 * trace._ + span.isFinished() + + when: "try to finish span again" + span.finish(*secondFinishCallArgs) + + then: "interceptors are not called" + interceptors.each({ interceptor -> + 0 * interceptor._ + }) + and: "trace is not informed" + 0 * trace.finishSpan(_, _) + and: "error is reported" + 1 * tracer.reportError(_, span) + + where: + name | method | methodArgs | expectedDuration | finalizeErrorReported | secondFinishCallArgs + "happy" | "finish" | [] | DURATION | false | [] + "happy" | "finish" | [] | DURATION | false | [222] + "happy with timestamp" | "finish" | [111] | DURATION + 111 | false | [222] + "happy with timestamp" | "finish" | [111] | DURATION + 111 | false | [] + // Note: doing GC tests with mocks is nearly impossible because mocks hold all sort of references + // We will do 'real' GC test as part of integration testing, this is more of a unit test + "finalized" | "finalize" | [] | DURATION | true | [] + "finalized" | "finalize" | [] | DURATION | true | [222] + } + + def "finished span GCed without errors"() { + setup: "create span" + def span = new SpanImpl(trace, parentContext, startTimestamp) + + when: "finish span" + span.finish() + + then: + span.isFinished() + 0 * tracer.reportError(_, *_) + + when: "finalize span" + span.finalize() + + then: + 0 * tracer.reportError(_, *_) + } + + def "finalize catches all exceptions"() { + setup: + def span = new SpanImpl(trace, parentContext, startTimestamp) + + when: + span.finalize() + + then: + 1 * startTimestamp.getDuration() >> { throw new Throwable() } + noExceptionThrown() + } + + def "span without timestamp"() { + when: + new SpanImpl(trace, parentContext, null) + + then: + thrown TraceException + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/TestUtils.java b/dd-trace/src/test/groovy/datadog/trace/tracer/TestUtils.java new file mode 100644 index 00000000000..354fdb433c2 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/TestUtils.java @@ -0,0 +1,21 @@ +package datadog.trace.tracer; + +import java.lang.ref.WeakReference; + +// TODO: stop copy-pasting this! +public class TestUtils { + + public static void awaitGC() { + Object obj = new Object(); + final WeakReference ref = new WeakReference<>(obj); + obj = null; + awaitGC(ref); + } + + public static void awaitGC(final WeakReference ref) { + while (ref.get() != null) { + System.gc(); + System.runFinalization(); + } + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/TimestampTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/TimestampTest.groovy new file mode 100644 index 00000000000..af1ed553cdd --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/TimestampTest.groovy @@ -0,0 +1,105 @@ +package datadog.trace.tracer + +import nl.jqno.equalsverifier.EqualsVerifier +import nl.jqno.equalsverifier.Warning +import spock.lang.Specification + +class TimestampTest extends Specification { + + private static final long CLOCK_START_TIME = 100 + private static final long CLOCK_START_NANO_TICKS = 300 + private static final long CLOCK_NANO_TICKS = 500 + + private static final long FINISH_NANO_TICKS = 600 + private static final long FINISH_TIME = 700 + + def tracer = Mock(Tracer) + def clock = Mock(Clock) { + getTracer() >> tracer + } + + def "test getter"() { + when: + def timestamp = new Timestamp(clock) + + then: + timestamp.getClock() == clock + } + + def "test getDuration with literal finish time"() { + setup: + clock.nanoTicks() >> CLOCK_NANO_TICKS + clock.getStartTimeNano() >> CLOCK_START_TIME + clock.getStartNanoTicks() >> CLOCK_START_NANO_TICKS + def timestamp = new Timestamp(clock) + + when: + def duration = timestamp.getDuration(FINISH_TIME) + + then: + duration == 400 + 0 * tracer._ + } + + def "test getDuration with timestamp '#name'"() { + setup: + clock.nanoTicks() >> startNanoTicks >> finishNanoTicks + def startTimestamp = new Timestamp(clock) + def finishTimestamp = new Timestamp(clock) + + when: + def duration = startTimestamp.getDuration(finishTimestamp) + + then: + duration == expectedDuration + 0 * tracer._ + + where: + name | startNanoTicks | finishNanoTicks | expectedDuration + 'normal' | CLOCK_START_NANO_TICKS | FINISH_NANO_TICKS | FINISH_NANO_TICKS - CLOCK_START_NANO_TICKS + 'overflow' | Long.MAX_VALUE - CLOCK_START_NANO_TICKS | Long.MIN_VALUE + FINISH_NANO_TICKS | FINISH_NANO_TICKS + CLOCK_START_NANO_TICKS + 1 + } + + def "test getDuration with current time"() { + setup: + clock.nanoTicks() >> CLOCK_START_NANO_TICKS >> FINISH_NANO_TICKS + def timestamp = new Timestamp(clock) + + when: + def duration = timestamp.getDuration() + + then: + duration == FINISH_NANO_TICKS - CLOCK_START_NANO_TICKS + 0 * tracer._ + } + + def "test getDuration with wrong clock"() { + setup: + clock.nanoTicks() >> CLOCK_NANO_TICKS + clock.getStartTimeNano() >> CLOCK_START_TIME + clock.getStartNanoTicks() >> CLOCK_START_NANO_TICKS + def timestamp = new Timestamp(clock) + def otherClock = Mock(Clock) { + getTracer() >> tracer + nanoTicks() >> CLOCK_NANO_TICKS + 400 + getStartTimeNano() >> CLOCK_START_TIME + 200 + getStartNanoTicks() >> CLOCK_START_NANO_TICKS + 100 + } + def finishTimestamp = new Timestamp(otherClock) + + when: + def duration = timestamp.getDuration(finishTimestamp) + + then: + duration == 500 + 1 * tracer.reportError(_, clock, otherClock) + } + + def "test equals"() { + when: + EqualsVerifier.forClass(Timestamp).suppress(Warning.STRICT_INHERITANCE).verify() + + then: + noExceptionThrown() + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/TraceExceptionTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/TraceExceptionTest.groovy new file mode 100644 index 00000000000..3bd3d0c0885 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/TraceExceptionTest.groovy @@ -0,0 +1,49 @@ +package datadog.trace.tracer + +import spock.lang.Specification + + +class TraceExceptionTest extends Specification { + + static final MESSAGE = "message" + + def "test default constructor"() { + when: + def exception = new TraceException() + + then: + exception != null + } + + def "test message constructor"() { + when: + def exception = new TraceException(MESSAGE) + + then: + exception.getMessage() == MESSAGE + } + + def "test cause constructor"() { + setup: + def cause = new RuntimeException() + + when: + def exception = new TraceException(cause) + + then: + exception.getCause() == cause + } + + def "test cause and message constructor"() { + setup: + def cause = new RuntimeException() + + when: + def exception = new TraceException(MESSAGE, cause) + + then: + exception.getMessage() == MESSAGE + exception.getCause() == cause + } + +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/TraceImplTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/TraceImplTest.groovy new file mode 100644 index 00000000000..2547ed83391 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/TraceImplTest.groovy @@ -0,0 +1,459 @@ +package datadog.trace.tracer + +import datadog.trace.tracer.sampling.Sampler +import datadog.trace.tracer.writer.Writer +import spock.lang.Specification + + +class TraceImplTest extends Specification { + + private static final String SERVICE_NAME = "service.name" + private static final String PARENT_TRACE_ID = "trace id" + private static final String PARENT_SPAN_ID = "span id" + + def interceptors = [ + Mock(name: "interceptor-1", Interceptor) { + beforeTraceWritten(_) >> { args -> args[0] } + }, + Mock(name: "interceptor-2", Interceptor) { + beforeTraceWritten(_) >> { args -> args[0] } + } + ] + def writer = Mock(Writer) + def sampler = Mock(Sampler) { + sample(_) >> true + } + def tracer = Mock(Tracer) { + getDefaultServiceName() >> SERVICE_NAME + getInterceptors() >> interceptors + getWriter() >> writer + getSampler() >> sampler + } + def parentContext = Mock(SpanContextImpl) { + getTraceId() >> PARENT_TRACE_ID + getSpanId() >> PARENT_SPAN_ID + } + def startTimestamp = Mock(Timestamp) + + def "test getters"() { + when: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + then: + trace.getTracer() == tracer + trace.getRootSpan().getTrace() == trace + trace.getRootSpan().getStartTimestamp() == startTimestamp + trace.getRootSpan().getContext().getTraceId() == PARENT_TRACE_ID + trace.getRootSpan().getContext().getParentId() == PARENT_SPAN_ID + trace.isValid() + } + + def "test getSpans on unfinished spans"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: + trace.getSpans() + + then: + 1 * tracer.reportError(_, trace) + } + + def "test timestamp creation"() { + setup: + def newTimestamp = Mock(Timestamp) + def clock = Mock(Clock) { + createCurrentTimestamp() >> newTimestamp + } + startTimestamp.getClock() >> clock + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: + def createdTimestamp = trace.createCurrentTimestamp() + + then: + createdTimestamp == newTimestamp + } + + def "finish root span"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: "interceptors get called" + interceptors.reverseEach({ interceptor -> + then: + 1 * interceptor.beforeTraceWritten(trace) >> trace + }) + then: "trace gets sampled" + 1 * sampler.sample(trace) >> { true } + then: "trace gets written" + 1 * writer.write(trace) + trace.isValid() + trace.getSpans() == [trace.getRootSpan()] + + when: "root span is finalized" + trace.getRootSpan().finalize() + + then: "nothing happens" + 0 * writer.incrementTraceCount() + interceptors.reverseEach({ interceptor -> + 0 * interceptor.beforeTraceWritten(_) + }) + 0 * sampler.sample(_) + 0 * writer.write(_) + 0 * tracer.reportError(_, *_) + } + + def "GC root span"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "root span is finalized" + trace.getRootSpan().finalize() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: "interceptors get called" + interceptors.reverseEach({ interceptor -> + then: + 1 * interceptor.beforeTraceWritten(trace) >> trace + }) + then: "trace gets sampled" + 1 * sampler.sample(trace) >> { true } + then: "trace gets written" + 1 * writer.write(trace) + !trace.isValid() + } + + def "finish root span dropped by interceptor"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: + trace.getRootSpan().finish() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: + 1 * interceptors[1].beforeTraceWritten(trace) >> null + 0 * interceptors[0].beforeTraceWritten(_) + 0 * sampler.sample(_) + 0 * writer.write(_) + } + + def "finish root span replaced by interceptor"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def replacementTrace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: + trace.getRootSpan().finish() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: + 1 * interceptors[1].beforeTraceWritten(trace) >> replacementTrace + then: + 1 * interceptors[0].beforeTraceWritten(replacementTrace) >> replacementTrace + then: + 1 * sampler.sample(replacementTrace) >> true + then: + 1 * writer.write(replacementTrace) + } + + def "finish root span dropped by sampler"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: + trace.getRootSpan().finish() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: + 1 * sampler.sample(trace) >> false + 0 * writer.write(_) + } + + def "finish root span and then finish it again by error"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: "interceptors get called" + interceptors.reverseEach({ interceptor -> + then: + 1 * interceptor.beforeTraceWritten(trace) >> trace + }) + then: "trace gets sampled" + 1 * sampler.sample(trace) >> { true } + then: "trace gets written" + 1 * writer.write(trace) + + when: "root span is finalized" + trace.finishSpan(trace.getRootSpan(), false) + + then: "error is reported" + interceptors.reverseEach({ interceptor -> + 0 * interceptor.beforeTraceWritten(_) + }) + 0 * sampler.sample(_) + 0 * writer.incrementTraceCount() + 0 * writer.write(_) + 1 * tracer.reportError(_, "finish span", trace) + } + + def "create and finish new span"() { + setup: + def newSpanTimestamp = Mock(Timestamp) + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "new span is created" + def span = trace.createSpan(trace.getRootSpan().getContext(), newSpanTimestamp) + + then: + span.getTrace() == trace + span.getStartTimestamp() == newSpanTimestamp + span.getContext().getTraceId() == PARENT_TRACE_ID + span.getContext().getParentId() == trace.getRootSpan().getContext().getSpanId() + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "nothing gets written" + 0 * writer.incrementTraceCount() + 0 * writer.write(_) + + when: "new span is finished" + span.finish() + + then: "trace gets written" + 1 * writer.incrementTraceCount() + 1 * writer.write(trace) + trace.isValid() + trace.getSpans() == [trace.getRootSpan(), span] + } + + def "create and finish new span with default timestamp"() { + setup: + def newSpanTimestamp = Mock(Timestamp) + def clock = Mock(Clock) { + createCurrentTimestamp() >> newSpanTimestamp + } + startTimestamp.getClock() >> clock + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "new span is created" + def span = trace.createSpan(trace.getRootSpan().getContext()) + + then: + span.getTrace() == trace + span.getStartTimestamp() == newSpanTimestamp + span.getContext().getTraceId() == PARENT_TRACE_ID + span.getContext().getParentId() == trace.getRootSpan().getContext().getSpanId() + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "nothing gets written" + 0 * writer.incrementTraceCount() + 0 * writer.write(_) + + when: "new span is finished" + span.finish() + + then: "trace gets written" + 1 * writer.incrementTraceCount() + 1 * writer.write(trace) + trace.isValid() + trace.getSpans() == [trace.getRootSpan(), span] + } + + def "create span on finished trace"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "trace is finished" + trace.getSpans() != [] + + when: "new span is created" + trace.createSpan(trace.getRootSpan().getContext(), startTimestamp) + + then: "error is reported" + 1 * tracer.reportError(_, "create span", trace) + } + + def "create span and finish it twice"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def span = trace.createSpan(trace.getRootSpan().getContext(), startTimestamp) + + when: "new span is created" + span.finish() + trace.finishSpan(span, true) + + then: "error is reported" + 1 * tracer.reportError(_, span, trace) + } + + def "create span with null parent context"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "new span with null parent context is created" + trace.createSpan(null, startTimestamp) + + then: "error is reported" + thrown TraceException + } + + def "create span with parent context from different trace"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def anotherParentContext = Mock(SpanContextImpl) { + getTraceId() >> "different trace" + getSpanId() >> PARENT_SPAN_ID + } + + when: "new span with null parent context is created" + trace.createSpan(anotherParentContext, startTimestamp) + + then: "error is reported" + thrown TraceException + } + + def "create and close new continuation"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "new continuation is created" + def continuation = trace.createContinuation(trace.getRootSpan()) + + then: + continuation.getSpan() == trace.getRootSpan() + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "nothing gets written" + 0 * writer.incrementTraceCount() + 0 * writer.write(_) + + when: "new continuation is closed" + continuation.close() + + then: "trace gets written" + 1 * writer.incrementTraceCount() + 1 * writer.write(trace) + trace.isValid() + trace.getSpans() == [trace.getRootSpan()] + } + + def "GC continuation"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def continuation = trace.createContinuation(trace.getRootSpan()) + trace.getRootSpan().finish() + + when: "continuation finalized" + continuation.finalize() + + then: "trace gets counted" + 1 * writer.incrementTraceCount() + then: "interceptors get called" + interceptors.reverseEach({ interceptor -> + then: + 1 * interceptor.beforeTraceWritten(trace) >> trace + }) + then: "trace gets sampled" + 1 * sampler.sample(trace) >> { true } + then: "trace gets written" + 1 * writer.write(trace) + !trace.isValid() + } + + def "create and close new continuation, then close it again"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def continuation = trace.createContinuation(trace.getRootSpan()) + continuation.close() + + when: "continuation is closed again" + trace.closeContinuation(continuation, true) + + then: "error is reported" + 1 * tracer.reportError(_, continuation, trace) + } + + def "create and close new continuation, then close it in finished trace"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def continuation = trace.createContinuation(trace.getRootSpan()) + continuation.close() + trace.getRootSpan().finish() + + when: "continuation is closed again" + trace.closeContinuation(continuation, true) + + then: "error is reported" + 1 * tracer.reportError(_, "close continuation", trace) + } + + def "create continuation on finished trace"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "root span is finished" + trace.getRootSpan().finish() + + then: "trace is finished" + trace.getSpans() != [] + + when: "new continuation is created" + trace.createContinuation(trace.getRootSpan()) + + then: "error is reported" + 1 * tracer.reportError(_, "create continuation", trace) + } + + def "create continuation with null parent span"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + + when: "new continuation with null parent span is created" + trace.createContinuation(null) + + then: "error is reported" + thrown TraceException + } + + def "create continuation with parent span from another trace"() { + setup: + def trace = new TraceImpl(tracer, parentContext, startTimestamp) + def anotherParentContext = Mock(SpanContextImpl) { + getTraceId() >> "different trace" + getSpanId() >> PARENT_SPAN_ID + } + def anotherParentSpan = Mock(SpanImpl) { + getContext() >> anotherParentContext + } + + when: "new continuation from span from another trace is created" + trace.createContinuation(anotherParentSpan) + + then: "error is reported" + thrown TraceException + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/TracerTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/TracerTest.groovy new file mode 100644 index 00000000000..39e67ccdae6 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/TracerTest.groovy @@ -0,0 +1,215 @@ +package datadog.trace.tracer + +import datadog.trace.api.Config +import datadog.trace.tracer.sampling.AllSampler +import datadog.trace.tracer.writer.LoggingWriter +import datadog.trace.tracer.writer.Writer +import spock.lang.Shared +import spock.lang.Specification + +import java.lang.ref.WeakReference +import java.util.concurrent.TimeUnit +import java.util.concurrent.atomic.AtomicInteger + +class TracerTest extends Specification { + + @Shared + def config = Config.get() + + def testWriter = new TestWriter() + + // TODO: add more tests for different config options and interceptors + def "test getters"() { + when: + def tracer = new Tracer(config) + + then: + tracer.getWriter() instanceof LoggingWriter + tracer.getSampler() instanceof AllSampler + tracer.getInterceptors() == [] + tracer.getDefaultServiceName() == config.getServiceName() + } + + def "test create current timestamp"() { + setup: + def tracer = new Tracer(config) + + when: + def timestamp = tracer.createCurrentTimestamp() + + then: + timestamp.getDuration() <= TimeUnit.MINUTES.toNanos(1) // Assume test takes less than a minute to run + } + + def "test trace happy path"() { + setup: + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: + def rootSpan = tracer.buildTrace(null) + def continuation = rootSpan.getTrace().createContinuation(rootSpan) + def span = rootSpan.getTrace().createSpan(rootSpan.getContext(), tracer.createCurrentTimestamp()) + + then: + rootSpan.getService() == config.getServiceName() + + when: + rootSpan.finish() + continuation.close() + + then: + testWriter.traces == [] + + when: + span.finish() + + then: + testWriter.traces == [rootSpan.getContext().getTraceId()] + testWriter.validity == [true] + rootSpan.getTrace().getSpans() == [rootSpan, span] + testWriter.traceCount.get() == 1 + } + + def "test inject"() { + //TODO implement this test properly + setup: + def context = Mock(SpanContext) + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: + tracer.inject(context, null, null) + + then: + noExceptionThrown() + } + + def "test extract"() { + //TODO implement this test properly + setup: + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: + def context = tracer.extract(null, null) + + then: + context == null + } + + def testReportError() { + //TODO implement this test properly + setup: + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: + tracer.reportError("message %s", 123) + + then: + thrown TraceException + } + + def "test trace that had a GCed span"() { + setup: + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: "trace and spans get created" + def rootSpan = tracer.buildTrace(null) + def traceId = rootSpan.getContext().getTraceId() + def span = rootSpan.getTrace().createSpan(rootSpan.getContext(), tracer.createCurrentTimestamp()) + rootSpan.finish() + + then: "nothing is written yet" + testWriter.traces == [] + + when: "remove all references to traces and spans and wait for GC" + span = null + def traceRef = new WeakReference<>(rootSpan.getTrace()) + rootSpan = null + TestUtils.awaitGC(traceRef) + + then: "invalid trace is written" + testWriter.waitForTraces(1) + testWriter.traces == [traceId] + testWriter.validity == [false] + testWriter.traceCount.get() == 1 + } + + def "test trace that had a GCed continuation"() { + setup: + def tracer = new Tracer(config, testWriter, new AllSampler(), []) + + when: "trace and spans get created" + def rootSpan = tracer.buildTrace(null) + def traceId = rootSpan.getContext().getTraceId() + def continuation = rootSpan.getTrace().createContinuation(rootSpan) + rootSpan.finish() + + then: "nothing is written yet" + testWriter.traces == [] + + when: "remove all references to traces and spans and wait for GC" + continuation = null + def traceRef = new WeakReference<>(rootSpan.getTrace()) + rootSpan = null + TestUtils.awaitGC(traceRef) + + then: "invalid trace is written" + testWriter.waitForTraces(1) + testWriter.traces == [traceId] + testWriter.validity == [false] + testWriter.traceCount.get() == 1 + } + + /** + * We cannot use mocks for testing of things related to GC because mocks capture arguments with hardlinks. + * For the same reason this test writer cannot capture complete references to traces in this writer. Instead + * we capture 'strategic' values. Other values have been tested in 'lower level' tests. + */ + static class TestWriter implements Writer { + + def traces = new ArrayList() + def validity = new ArrayList() + def traceCount = new AtomicInteger() + + @Override + synchronized void write(Trace trace) { + traces.add(trace.getRootSpan().getContext().getTraceId()) + validity.add(trace.isValid()) + } + + @Override + void incrementTraceCount() { + traceCount.incrementAndGet() + } + + @Override + void start() { + //nothing to do for now + } + + @Override + void close() { + //nothing to do for now + } + + /** + * JVM gives very little guarantees for when finalizers are run. {@link WeakReference} documentation + * says that weak reference is set to null first, and then objects are marked as finalizable. Then + * finalization happens asynchronously in separate thread. + * This means that currently we do not have a good way of knowing that all traces have been closed/GCed right + * now and only thing we can do is to bluntly wait. + * In the future we have plans to implement limiting of number of inflight traces - this might provide us with + * better way. + * @param numberOfTraces number of traces to wait for. + */ + void waitForTraces(int numberOfTraces) { + while (true) { + synchronized (this) { + if (traces.size() >= numberOfTraces && validity.size() >= numberOfTraces) { + return + } + } + Thread.sleep(500) + } + } + } +} diff --git a/dd-trace/src/test/groovy/datadog/trace/tracer/writer/LoggingWriterTest.groovy b/dd-trace/src/test/groovy/datadog/trace/tracer/writer/LoggingWriterTest.groovy new file mode 100644 index 00000000000..805a7141ef9 --- /dev/null +++ b/dd-trace/src/test/groovy/datadog/trace/tracer/writer/LoggingWriterTest.groovy @@ -0,0 +1,40 @@ +package datadog.trace.tracer.writer + +import datadog.trace.tracer.Trace +import spock.lang.Shared +import spock.lang.Specification + +// TODO: this test set is incomplete, fill it in +class LoggingWriterTest extends Specification { + + @Shared + def writer = new LoggingWriter() + + def "test start"() { + when: + writer.start() + + then: + noExceptionThrown() + } + + def "test close"() { + when: + writer.close() + + then: + noExceptionThrown() + } + + def "test write"() { + setup: + def trace = Mock(Trace) + + when: + writer.write(trace) + + then: + 1 * trace.toString() + } + +}