Fix clock problem with OT API

Author: felixbarny

apm-agent-core/src/main/java/co/elastic/apm/impl/transaction/Span.java

@@ -43,7 +43,8 @@ public Span(ElasticApmTracer tracer) {
     }
 
     public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T parentContext) {
-        return start(childContextCreator, parentContext, getTraceContext().getClock().getEpochMicros());
+        // we can't get the timestamp here as the clock has not yet been initialized
+        return start(childContextCreator, parentContext, -1);
     }
 
     public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T parentContext, long epochMicros) {
@@ -56,7 +57,11 @@ public <T> Span start(TraceContext.ChildContextCreator<T> childContextCreator, T
         if (dropped) {
             traceContext.setRecorded(false);
         }
-        timestamp = epochMicros;
+        if (epochMicros >= 0) {
+            timestamp = epochMicros;
+        } else {
+            timestamp = getTraceContext().getClock().getEpochMicros();
+        }
         if (logger.isDebugEnabled()) {
             logger.debug("startSpan {} {", this);
             if (logger.isTraceEnabled()) {

apm-opentracing/src/test/java/co/elastic/apm/opentracing/OpenTracingBridgeTest.java

@@ -20,11 +20,13 @@
 package co.elastic.apm.opentracing;
 
 import co.elastic.apm.AbstractInstrumentationTest;
+import co.elastic.apm.impl.transaction.SystemClock;
 import co.elastic.apm.impl.transaction.TraceContext;
 import co.elastic.apm.impl.transaction.Transaction;
 import io.opentracing.Scope;
 import io.opentracing.Span;
 import io.opentracing.SpanContext;
+import io.opentracing.Tracer;
 import io.opentracing.log.Fields;
 import io.opentracing.propagation.Format;
 import io.opentracing.propagation.TextMapExtractAdapter;
@@ -64,6 +66,22 @@ void testCreateNonActiveTransaction() {
         assertThat(reporter.getFirstTransaction().getName().toString()).isEqualTo("test");
     }
 
+    @Test
+    void sanityCheckRealTimestamps() {
+        final Span transactionSpan = apmTracer.buildSpan("transactionSpan").start();
+        apmTracer.buildSpan("nestedSpan").asChildOf(transactionSpan).start().finish();
+        transactionSpan.finish();
+        final long epochMicros = SystemClock.ForJava8CapableVM.INSTANCE.getEpochMicros();
+
+        assertThat(reporter.getTransactions()).hasSize(1);
+        assertThat(reporter.getFirstTransaction().getDuration()).isLessThan(TimeUnit.MINUTES.toMillis(1));
+        assertThat(reporter.getFirstTransaction().getTimestamp()).isBetween(epochMicros - TimeUnit.MINUTES.toMicros(1), epochMicros);
+
+        assertThat(reporter.getSpans()).hasSize(1);
+        assertThat(reporter.getFirstSpan().getDuration()).isLessThan(TimeUnit.MINUTES.toMillis(1));
+        assertThat(reporter.getFirstSpan().getTimestamp()).isBetween(epochMicros - TimeUnit.MINUTES.toMicros(1), epochMicros);
+    }
+
     @Test
     void testFinishTwice() {
         final Span span = apmTracer.buildSpan("test").withStartTimestamp(0).start();
@@ -153,7 +171,7 @@ void testCreateNonActiveTransactionAsChildOf() {
 
     @Test
     void testCreateActiveTransaction() {
-        final ApmScope scope = apmTracer.buildSpan("test").withStartTimestamp(0).startActive(false);
+        final ApmScope scope = (ApmScope) apmTracer.buildSpan("test").withStartTimestamp(0).startActive(false);
 
         assertThat(apmTracer.activeSpan()).isNotNull();
         assertThat(apmTracer.activeSpan().getSpan()).isSameAs(scope.span().getSpan());
@@ -173,9 +191,9 @@ void testCreateActiveTransaction() {
 
     @Test
     void testCreateActiveTransactionAndSpans() {
-        try (ApmScope transaction = apmTracer.buildSpan("transaction").startActive(true)) {
-            try (ApmScope span = apmTracer.buildSpan("span").startActive(true)) {
-                try (ApmScope nestedSpan = apmTracer.buildSpan("nestedSpan").startActive(true)) {
+        try (Scope transaction = apmTracer.buildSpan("transaction").startActive(true)) {
+            try (Scope span = apmTracer.buildSpan("span").startActive(true)) {
+                try (Scope nestedSpan = apmTracer.buildSpan("nestedSpan").startActive(true)) {
                 }
             }
         }
@@ -217,10 +235,10 @@ void testResolveServerType() {
     @Test
     void testCreatingClientTransactionCreatesNoopSpan() {
         assertThat(apmTracer.scopeManager().active()).isNull();
-        try (ApmScope transactionScope = apmTracer.buildSpan("transaction").withTag("span.kind", "client").startActive(true)) {
-            try (ApmScope spanScope = apmTracer.buildSpan("span").startActive(true)) {
+        try (ApmScope transactionScope = (ApmScope) apmTracer.buildSpan("transaction").withTag("span.kind", "client").startActive(true)) {
+            try (ApmScope spanScope = (ApmScope) apmTracer.buildSpan("span").startActive(true)) {
                 assertThat(apmTracer.scopeManager().active().span().getSpan()).isEqualTo(spanScope.span().getSpan());
-                try (ApmScope nestedSpanScope = apmTracer.buildSpan("nestedSpan").startActive(true)) {
+                try (ApmScope nestedSpanScope = (ApmScope) apmTracer.buildSpan("nestedSpan").startActive(true)) {
                     assertThat(apmTracer.scopeManager().active().span().getSpan()).isEqualTo(nestedSpanScope.span().getSpan());
                 }
                 assertThat(apmTracer.scopeManager().active().span().getSpan()).isEqualTo(spanScope.span().getSpan());
@@ -344,7 +362,7 @@ void testAsChildOfSpanNull() {
 
     @Test
     void testGetBaggageItem() {
-        final ApmSpan span = apmTracer.buildSpan("span")
+        final Span span = apmTracer.buildSpan("span")
             .start();
 
         // baggage is not supported yet
@@ -355,8 +373,8 @@ void testGetBaggageItem() {
 
     @Test
     void testSpanTags() {
-        try (ApmScope transaction = apmTracer.buildSpan("transaction").startActive(true)) {
-            try (ApmScope span = apmTracer.buildSpan("span").startActive(true)) {
+        try (Scope transaction = apmTracer.buildSpan("transaction").startActive(true)) {
+            try (Scope span = apmTracer.buildSpan("span").startActive(true)) {
                 transaction.span().setTag("foo", "bar");
                 span.span().setTag("bar", "baz");
             }
@@ -368,7 +386,7 @@ void testSpanTags() {
     }
 
     private Transaction createTransactionFromOtTags(Map<String, String> tags) {
-        final ApmSpanBuilder spanBuilder = apmTracer.buildSpan("transaction");
+        final Tracer.SpanBuilder spanBuilder = apmTracer.buildSpan("transaction");
         tags.forEach(spanBuilder::withTag);
         spanBuilder.start().finish();
         assertThat(reporter.getTransactions()).hasSize(1);
@@ -378,9 +396,9 @@ private Transaction createTransactionFromOtTags(Map<String, String> tags) {
     }
 
     private co.elastic.apm.impl.transaction.Span createSpanFromOtTags(Map<String, String> tags) {
-        final ApmSpanBuilder transactionSpanBuilder = apmTracer.buildSpan("transaction");
+        final Tracer.SpanBuilder transactionSpanBuilder = apmTracer.buildSpan("transaction");
         try (Scope transaction = transactionSpanBuilder.startActive(true)) {
-            final ApmSpanBuilder spanBuilder = apmTracer.buildSpan("transaction");
+            final Tracer.SpanBuilder spanBuilder = apmTracer.buildSpan("transaction");
             tags.forEach(spanBuilder::withTag);
             spanBuilder.start().finish();
         }