From 260c60378420c81f0e2e5c6aa26766531fe080a1 Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Sat, 20 Nov 2021 10:42:06 -0800 Subject: [PATCH] Fix exemplars (#4678) --- .../api/instrumenter/Instrumenter.java | 16 ++++- .../api/instrumenter/InstrumenterBuilder.java | 3 +- .../instrumenter/http/HttpClientMetrics.java | 3 +- .../instrumenter/http/HttpServerMetrics.java | 5 +- .../api/instrumenter/InstrumenterTest.java | 34 ++++++++++ .../http/HttpClientMetricsTest.java | 41 ++++++++--- .../http/HttpServerMetricsTest.java | 68 +++++++++++++------ 7 files changed, 132 insertions(+), 38 deletions(-) diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java index 1dba5c526c..a33f33b0c4 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/Instrumenter.java @@ -100,6 +100,7 @@ public class Instrumenter { attributesExtractors; private final List> contextCustomizers; private final List requestListeners; + private final List requestMetricListeners; private final ErrorCauseExtractor errorCauseExtractor; @Nullable private final StartTimeExtractor startTimeExtractor; @Nullable private final EndTimeExtractor endTimeExtractor; @@ -117,6 +118,7 @@ public class Instrumenter { this.attributesExtractors = new ArrayList<>(builder.attributesExtractors); this.contextCustomizers = new ArrayList<>(builder.contextCustomizers); this.requestListeners = new ArrayList<>(builder.requestListeners); + this.requestMetricListeners = new ArrayList<>(builder.requestMetricListeners); this.errorCauseExtractor = builder.errorCauseExtractor; this.startTimeExtractor = builder.startTimeExtractor; this.endTimeExtractor = builder.endTimeExtractor; @@ -192,6 +194,15 @@ public class Instrumenter { Span span = spanBuilder.startSpan(); context = context.with(span); + // request metric listeners need to run after the span has been added to the context in order + // for them to generate exemplars + if (!requestMetricListeners.isEmpty()) { + long startNanos = getNanos(startTime); + for (RequestListener requestListener : requestMetricListeners) { + context = requestListener.start(context, attributes, startNanos); + } + } + return spanSuppressionStrategy.storeInContext(context, spanKind, span); } @@ -221,11 +232,14 @@ public class Instrumenter { endTime = endTimeExtractor.extract(request, response, error); } - if (!requestListeners.isEmpty()) { + if (!requestListeners.isEmpty() || !requestMetricListeners.isEmpty()) { long endNanos = getNanos(endTime); for (RequestListener requestListener : requestListeners) { requestListener.end(context, attributes, endNanos); } + for (RequestListener requestListener : requestMetricListeners) { + requestListener.end(context, attributes, endNanos); + } } StatusCode statusCode = spanStatusExtractor.extract(request, response, error); diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterBuilder.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterBuilder.java index 18b7fa0e04..29d140abf2 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterBuilder.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterBuilder.java @@ -50,6 +50,7 @@ public final class InstrumenterBuilder { new ArrayList<>(); final List> contextCustomizers = new ArrayList<>(); final List requestListeners = new ArrayList<>(); + final List requestMetricListeners = new ArrayList<>(); SpanKindExtractor spanKindExtractor = SpanKindExtractor.alwaysInternal(); SpanStatusExtractor spanStatusExtractor = @@ -124,7 +125,7 @@ public final class InstrumenterBuilder { /** Adds a {@link RequestMetrics} whose metrics will be recorded for request start and stop. */ @UnstableApi public InstrumenterBuilder addRequestMetrics(RequestMetrics factory) { - requestListeners.add(factory.create(meter)); + requestMetricListeners.add(factory.create(meter)); return this; } diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java index 0f32fc1519..d884bdea02 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetrics.java @@ -76,7 +76,8 @@ public final class HttpClientMetrics implements RequestListener { } duration.record( (endNanos - state.startTimeNanos()) / NANOS_PER_MS, - applyClientDurationView(state.startAttributes(), endAttributes)); + applyClientDurationView(state.startAttributes(), endAttributes), + context); } @AutoValue diff --git a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java index 426728a095..d442630b51 100644 --- a/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java +++ b/instrumentation-api/src/main/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetrics.java @@ -71,7 +71,7 @@ public final class HttpServerMetrics implements RequestListener { @Override public Context start(Context context, Attributes startAttributes, long startNanos) { - activeRequests.add(1, applyActiveRequestsView(startAttributes)); + activeRequests.add(1, applyActiveRequestsView(startAttributes), context); return context.with( HTTP_SERVER_REQUEST_METRICS_STATE, @@ -89,7 +89,8 @@ public final class HttpServerMetrics implements RequestListener { activeRequests.add(-1, applyActiveRequestsView(state.startAttributes())); duration.record( (endNanos - state.startTimeNanos()) / NANOS_PER_MS, - applyServerDurationView(state.startAttributes(), endAttributes)); + applyServerDurationView(state.startAttributes(), endAttributes), + context); } @AutoValue diff --git a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterTest.java b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterTest.java index 1786fc431a..528be0ce3d 100644 --- a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterTest.java +++ b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/InstrumenterTest.java @@ -10,6 +10,7 @@ import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.attri import static org.assertj.core.api.Assertions.entry; import static org.mockito.Mockito.when; +import io.opentelemetry.api.common.Attributes; import io.opentelemetry.api.common.AttributesBuilder; import io.opentelemetry.api.trace.Span; import io.opentelemetry.api.trace.SpanContext; @@ -39,6 +40,7 @@ import java.time.Instant; import java.util.Collections; import java.util.HashMap; import java.util.Map; +import java.util.concurrent.atomic.AtomicReference; import java.util.stream.Collectors; import java.util.stream.Stream; import javax.annotation.Nullable; @@ -410,6 +412,38 @@ class InstrumenterTest { .hasParentSpanId("090a0b0c0d0e0f00"))); } + @Test + void requestMetrics() { + AtomicReference startContext = new AtomicReference<>(); + AtomicReference endContext = new AtomicReference<>(); + + RequestListener requestListener = + new RequestListener() { + @Override + public Context start(Context context, Attributes startAttributes, long startNanos) { + startContext.set(context); + return context; + } + + @Override + public void end(Context context, Attributes endAttributes, long endNanos) { + endContext.set(context); + } + }; + + Instrumenter, Map> instrumenter = + Instrumenter., Map>builder( + otelTesting.getOpenTelemetry(), "test", unused -> "span") + .addRequestMetrics(meter -> requestListener) + .newServerInstrumenter(new MapGetter()); + + Context context = instrumenter.start(Context.root(), REQUEST); + instrumenter.end(context, REQUEST, RESPONSE, null); + + assertThat(Span.fromContext(startContext.get()).getSpanContext().isValid()).isTrue(); + assertThat(Span.fromContext(endContext.get()).getSpanContext().isValid()).isTrue(); + } + @Test void shouldStartSpanWithGivenStartTime() { // given diff --git a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java index 11d616c47a..ee8a7b6f12 100644 --- a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java +++ b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpClientMetricsTest.java @@ -10,6 +10,10 @@ import static io.opentelemetry.sdk.testing.assertj.metrics.MetricAssertions.asse import static org.awaitility.Awaitility.await; import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanContext; +import io.opentelemetry.api.trace.TraceFlags; +import io.opentelemetry.api.trace.TraceState; import io.opentelemetry.context.Context; import io.opentelemetry.instrumentation.api.instrumenter.RequestListener; import io.opentelemetry.sdk.metrics.SdkMeterProvider; @@ -47,7 +51,17 @@ class HttpClientMetricsTest { .put("http.status_code", 200) .build(); - Context context1 = listener.start(Context.current(), requestAttributes, nanos(100)); + Context parent = + Context.root() + .with( + Span.wrap( + SpanContext.create( + "ff01020304050600ff0a0b0c0d0e0f00", + "090a0b0c0d0e0f00", + TraceFlags.getSampled(), + TraceState.getDefault()))); + + Context context1 = listener.start(parent, requestAttributes, nanos(100)); // TODO(anuraaga): Remove await from this file after 1.8.0 hopefully fixes // https://github.com/open-telemetry/opentelemetry-java/issues/3725 @@ -58,7 +72,7 @@ class HttpClientMetricsTest { assertThat(metrics).isEmpty(); }); - Context context2 = listener.start(Context.current(), requestAttributes, nanos(150)); + Context context2 = listener.start(Context.root(), requestAttributes, nanos(150)); await() .untilAsserted( @@ -82,15 +96,20 @@ class HttpClientMetricsTest { .hasDoubleHistogram() .points() .satisfiesExactly( - point -> - assertThat(point) - .hasSum(150 /* millis */) - .attributes() - .containsOnly( - attributeEntry("http.url", "https://localhost:1234/"), - attributeEntry("http.method", "GET"), - attributeEntry("http.flavor", "2.0"), - attributeEntry("http.status_code", 200)))); + point -> { + assertThat(point) + .hasSum(150 /* millis */) + .attributes() + .containsOnly( + attributeEntry("http.url", "https://localhost:1234/"), + attributeEntry("http.method", "GET"), + attributeEntry("http.flavor", "2.0"), + attributeEntry("http.status_code", 200)); + assertThat(point).exemplars().hasSize(1); + assertThat(point.getExemplars().get(0)) + .hasTraceId("ff01020304050600ff0a0b0c0d0e0f00") + .hasSpanId("090a0b0c0d0e0f00"); + })); }); listener.end(context2, responseAttributes, nanos(300)); diff --git a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java index c189c6ba23..c575cf946c 100644 --- a/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java +++ b/instrumentation-api/src/test/java/io/opentelemetry/instrumentation/api/instrumenter/http/HttpServerMetricsTest.java @@ -10,6 +10,10 @@ import static io.opentelemetry.sdk.testing.assertj.metrics.MetricAssertions.asse import static org.awaitility.Awaitility.await; import io.opentelemetry.api.common.Attributes; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanContext; +import io.opentelemetry.api.trace.TraceFlags; +import io.opentelemetry.api.trace.TraceState; import io.opentelemetry.context.Context; import io.opentelemetry.instrumentation.api.instrumenter.RequestListener; import io.opentelemetry.sdk.metrics.SdkMeterProvider; @@ -23,7 +27,7 @@ class HttpServerMetricsTest { @Test void collectsMetrics() { - InMemoryMetricReader metricReader = new InMemoryMetricReader(); + InMemoryMetricReader metricReader = InMemoryMetricReader.create(); SdkMeterProvider meterProvider = SdkMeterProvider.builder().registerMetricReader(metricReader).build(); @@ -46,7 +50,17 @@ class HttpServerMetricsTest { .put("http.status_code", 200) .build(); - Context context1 = listener.start(Context.current(), requestAttributes, nanos(100)); + Context parent = + Context.root() + .with( + Span.wrap( + SpanContext.create( + "ff01020304050600ff0a0b0c0d0e0f00", + "090a0b0c0d0e0f00", + TraceFlags.getSampled(), + TraceState.getDefault()))); + + Context context1 = listener.start(parent, requestAttributes, nanos(100)); // TODO(anuraaga): Remove await from this file after 1.8.0 hopefully fixes // https://github.com/open-telemetry/opentelemetry-java/issues/3725 @@ -66,17 +80,22 @@ class HttpServerMetricsTest { .hasLongSum() .points() .satisfiesExactly( - point -> - assertThat(point) - .hasValue(1) - .attributes() - .containsOnly( - attributeEntry("http.host", "host"), - attributeEntry("http.method", "GET"), - attributeEntry("http.scheme", "https")))); + point -> { + assertThat(point) + .hasValue(1) + .attributes() + .containsOnly( + attributeEntry("http.host", "host"), + attributeEntry("http.method", "GET"), + attributeEntry("http.scheme", "https")); + assertThat(point).exemplars().hasSize(1); + assertThat(point.getExemplars().get(0)) + .hasTraceId("ff01020304050600ff0a0b0c0d0e0f00") + .hasSpanId("090a0b0c0d0e0f00"); + })); }); - Context context2 = listener.start(Context.current(), requestAttributes, nanos(150)); + Context context2 = listener.start(Context.root(), requestAttributes, nanos(150)); await() .untilAsserted( @@ -116,17 +135,22 @@ class HttpServerMetricsTest { .hasDoubleHistogram() .points() .satisfiesExactly( - point -> - assertThat(point) - .hasSum(150 /* millis */) - .attributes() - .containsOnly( - attributeEntry("http.scheme", "https"), - attributeEntry("http.host", "host"), - attributeEntry("http.target", "/"), - attributeEntry("http.method", "GET"), - attributeEntry("http.status_code", 200), - attributeEntry("http.flavor", "2.0")))); + point -> { + assertThat(point) + .hasSum(150 /* millis */) + .attributes() + .containsOnly( + attributeEntry("http.scheme", "https"), + attributeEntry("http.host", "host"), + attributeEntry("http.target", "/"), + attributeEntry("http.method", "GET"), + attributeEntry("http.status_code", 200), + attributeEntry("http.flavor", "2.0")); + assertThat(point).exemplars().hasSize(1); + assertThat(point.getExemplars().get(0)) + .hasTraceId("ff01020304050600ff0a0b0c0d0e0f00") + .hasSpanId("090a0b0c0d0e0f00"); + })); }); listener.end(context2, responseAttributes, nanos(300));