Move client span creation to decorator and automatically suppress creation of neste… (#460)

* Move client span creation to decorator and suppress creation of nested client spans.

* Store subtree client span in context.

* Apply new pattern to AWS V1 SDK instrumentation too, cleanup, and javadoc
This commit is contained in:
Anuraag Agrawal 2020-06-09 04:01:43 +09:00 committed by GitHub
parent 8ee54389da
commit f13a9c4932
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 148 additions and 177 deletions

View File

@ -15,10 +15,49 @@
*/
package io.opentelemetry.auto.bootstrap.instrumentation.decorator;
import io.grpc.Context;
import io.opentelemetry.trace.DefaultSpan;
import io.opentelemetry.trace.Span;
import io.opentelemetry.trace.Span.Kind;
import io.opentelemetry.trace.Tracer;
import io.opentelemetry.trace.TracingContextUtils;
public abstract class ClientDecorator extends BaseDecorator {
// Keeps track of the client span in a subtree corresponding to a client request.
// Visible for testing
static final Context.Key<Span> CONTEXT_CLIENT_SPAN_KEY =
Context.key("opentelemetry-trace-auto-client-span-key");
/**
* Returns a new {@link Context} forked from the {@linkplain Context#current()} current context}
* with the {@link Span} set.
*/
public static Context currentContextWith(final Span clientSpan) {
Context context = Context.current();
if (clientSpan.getContext().isValid()) {
context = context.withValue(CONTEXT_CLIENT_SPAN_KEY, clientSpan);
}
return TracingContextUtils.withSpan(clientSpan, context);
}
/**
* Returns a new client {@link Span} if there is no client {@link Span} in the current {@link
* Context}, or an invalid {@link Span} otherwise.
*/
public static Span getOrCreateSpan(String name, Tracer tracer) {
final Context context = Context.current();
final Span clientSpan = CONTEXT_CLIENT_SPAN_KEY.get(context);
if (clientSpan != null) {
// We don't want to create two client spans for a given client call, suppress inner spans.
return DefaultSpan.getInvalid();
}
final Span current = TracingContextUtils.getSpan(context);
return tracer.spanBuilder(name).setSpanKind(Kind.CLIENT).setParent(current).startSpan();
}
@Override
public Span afterStart(final Span span) {
assert span != null;

View File

@ -20,6 +20,7 @@ import io.opentelemetry.auto.instrumentation.api.MoreTags;
import io.opentelemetry.auto.instrumentation.api.Tags;
import io.opentelemetry.trace.Span;
import io.opentelemetry.trace.Status;
import io.opentelemetry.trace.Tracer;
import java.net.URI;
import java.net.URISyntaxException;
import lombok.extern.slf4j.Slf4j;
@ -35,6 +36,10 @@ public abstract class HttpClientDecorator<REQUEST, RESPONSE> extends ClientDecor
protected abstract Integer status(RESPONSE response);
public Span getOrCreateSpan(REQUEST request, Tracer tracer) {
return getOrCreateSpan(spanNameForRequest(request), tracer);
}
public String spanNameForRequest(final REQUEST request) {
if (request == null) {
return DEFAULT_SPAN_NAME;

View File

@ -15,10 +15,17 @@
*/
package io.opentelemetry.auto.bootstrap.instrumentation.decorator
import io.grpc.Context
import io.opentelemetry.OpenTelemetry
import io.opentelemetry.context.ContextUtils
import io.opentelemetry.trace.Span
import io.opentelemetry.trace.Tracer
import io.opentelemetry.trace.TracingContextUtils
class ClientDecoratorTest extends BaseDecoratorTest {
private static final Tracer TRACER = OpenTelemetry.getTracerProvider().get("io.opentelemetry.auto")
def span = Mock(Span)
def "test afterStart"() {
@ -44,6 +51,60 @@ class ClientDecoratorTest extends BaseDecoratorTest {
0 * _
}
def "test getOrCreateSpan when no existing client span"() {
when:
def span = ClientDecorator.getOrCreateSpan("test", TRACER)
then:
assert span.getContext().isValid()
}
def "test getOrCreateSpan when existing client span"() {
setup:
def existing = ClientDecorator.getOrCreateSpan("existing", TRACER)
def scope = ContextUtils.withScopedContext(ClientDecorator.currentContextWith(existing))
when:
def span = ClientDecorator.getOrCreateSpan("test", TRACER)
then:
assert !span.getContext().isValid()
cleanup:
scope.close()
}
def "test getOrCreateSpan internal after client span"() {
setup:
def client = ClientDecorator.getOrCreateSpan("existing", TRACER)
def scope = ContextUtils.withScopedContext(ClientDecorator.currentContextWith(client))
when:
def internal = TRACER.spanBuilder("internal").setSpanKind(Span.Kind.INTERNAL).startSpan()
def scope2 = TracingContextUtils.currentContextWith(internal)
then:
assert internal.getContext().isValid()
assert ClientDecorator.CONTEXT_CLIENT_SPAN_KEY.get(Context.current()) == client
assert TracingContextUtils.getSpan(Context.current()) == internal
cleanup:
scope2.close()
scope.close()
}
def "test currentContextWith"() {
setup:
def span = ClientDecorator.getOrCreateSpan("test", TRACER)
when:
def context = ClientDecorator.currentContextWith(span)
then:
assert ClientDecorator.CONTEXT_CLIENT_SPAN_KEY.get(context) == span
assert TracingContextUtils.getSpan(context) == span
}
@Override
def newDecorator() {
return newDecorator("test-service")

View File

@ -17,6 +17,7 @@ package io.opentelemetry.instrumentation.awssdk.v2_2;
import static io.opentelemetry.instrumentation.awssdk.v2_2.AwsSdkClientDecorator.DECORATE;
import io.opentelemetry.auto.bootstrap.instrumentation.decorator.ClientDecorator;
import io.opentelemetry.trace.Span;
import io.opentelemetry.trace.Span.Kind;
import software.amazon.awssdk.core.interceptor.Context;
@ -40,10 +41,7 @@ final class TracingExecutionInterceptor implements ExecutionInterceptor {
public void beforeExecution(
final Context.BeforeExecution context, final ExecutionAttributes executionAttributes) {
final Span span =
AwsSdk.tracer()
.spanBuilder(DECORATE.spanName(executionAttributes))
.setSpanKind(kind)
.startSpan();
ClientDecorator.getOrCreateSpan(DECORATE.spanName(executionAttributes), AwsSdk.tracer());
DECORATE.afterStart(span);
executionAttributes.putAttribute(SPAN_ATTRIBUTE, span);
}

View File

@ -21,8 +21,6 @@ import static io.opentelemetry.auto.instrumentation.apachehttpclient.v4_0.HttpHe
import static io.opentelemetry.auto.tooling.ClassLoaderMatcher.hasClassesNamed;
import static io.opentelemetry.auto.tooling.bytebuddy.matcher.AgentElementMatchers.implementsInterface;
import static io.opentelemetry.context.ContextUtils.withScopedContext;
import static io.opentelemetry.trace.Span.Kind.CLIENT;
import static io.opentelemetry.trace.TracingContextUtils.withSpan;
import static net.bytebuddy.matcher.ElementMatchers.isAbstract;
import static net.bytebuddy.matcher.ElementMatchers.isMethod;
import static net.bytebuddy.matcher.ElementMatchers.named;
@ -34,6 +32,7 @@ import com.google.auto.service.AutoService;
import io.grpc.Context;
import io.opentelemetry.OpenTelemetry;
import io.opentelemetry.auto.bootstrap.CallDepthThreadLocalMap;
import io.opentelemetry.auto.bootstrap.instrumentation.decorator.ClientDecorator;
import io.opentelemetry.auto.instrumentation.api.SpanWithScope;
import io.opentelemetry.auto.tooling.Instrumenter;
import io.opentelemetry.context.Scope;
@ -172,16 +171,13 @@ public class ApacheHttpClientInstrumentation extends Instrumenter.Default {
public static class HelperMethods {
public static SpanWithScope doMethodEnter(final HttpUriRequest request) {
final Span span =
TRACER.spanBuilder(DECORATE.spanNameForRequest(request)).setSpanKind(CLIENT).startSpan();
final Span span = DECORATE.getOrCreateSpan(request, TRACER);
DECORATE.afterStart(span);
DECORATE.onRequest(span, request);
final Context context = withSpan(span, Context.current());
final boolean awsClientCall = request.getHeaders("amz-sdk-invocation-id").length > 0;
// AWS calls are often signed, so we can't add headers without breaking the signature.
if (!awsClientCall) {
final Context context = ClientDecorator.currentContextWith(span);
if (span.getContext().isValid()) {
OpenTelemetry.getPropagators().getHttpTextFormat().inject(context, request, SETTER);
}
final Scope scope = withScopedContext(context);

View File

@ -16,7 +16,6 @@
package io.opentelemetry.auto.instrumentation.awssdk.v1_11;
import static io.opentelemetry.auto.instrumentation.awssdk.v1_11.RequestMeta.SPAN_SCOPE_PAIR_CONTEXT_KEY;
import static io.opentelemetry.trace.TracingContextUtils.currentContextWith;
import com.amazonaws.AmazonWebServiceRequest;
import com.amazonaws.Request;
@ -24,7 +23,9 @@ import com.amazonaws.Response;
import com.amazonaws.handlers.RequestHandler2;
import io.opentelemetry.OpenTelemetry;
import io.opentelemetry.auto.bootstrap.ContextStore;
import io.opentelemetry.auto.bootstrap.instrumentation.decorator.ClientDecorator;
import io.opentelemetry.auto.instrumentation.api.SpanWithScope;
import io.opentelemetry.context.ContextUtils;
import io.opentelemetry.trace.Span;
import io.opentelemetry.trace.Tracer;
@ -47,11 +48,13 @@ public class TracingRequestHandler extends RequestHandler2 {
@Override
public void beforeRequest(final Request<?> request) {
final Span span = TRACER.spanBuilder(decorate.spanNameForRequest(request)).startSpan();
final Span span = decorate.getOrCreateSpan(request, TRACER);
decorate.afterStart(span);
decorate.onRequest(span, request);
request.addHandlerContext(
SPAN_SCOPE_PAIR_CONTEXT_KEY, new SpanWithScope(span, currentContextWith(span)));
SPAN_SCOPE_PAIR_CONTEXT_KEY,
new SpanWithScope(
span, ContextUtils.withScopedContext(ClientDecorator.currentContextWith(span))));
}
@Override

View File

@ -47,8 +47,6 @@ import io.opentelemetry.auto.bootstrap.instrumentation.decorator.HttpClientDecor
import io.opentelemetry.auto.instrumentation.api.MoreTags
import io.opentelemetry.auto.instrumentation.api.Tags
import io.opentelemetry.auto.test.AgentTestRunner
import org.apache.http.conn.HttpHostConnectException
import org.apache.http.impl.execchain.RequestAbortedException
import spock.lang.AutoCleanup
import spock.lang.Shared
@ -57,7 +55,6 @@ import java.util.concurrent.atomic.AtomicReference
import static io.opentelemetry.auto.test.server.http.TestHttpServer.httpServer
import static io.opentelemetry.auto.test.utils.PortUtils.UNUSABLE_PORT
import static io.opentelemetry.trace.Span.Kind.CLIENT
import static io.opentelemetry.trace.Span.Kind.INTERNAL
class AWS1ClientTest extends AgentTestRunner {
@ -149,10 +146,10 @@ class AWS1ClientTest extends AgentTestRunner {
client.requestHandler2s.get(0).getClass().getSimpleName() == "TracingRequestHandler"
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored false
parent()
tags {
@ -170,19 +167,6 @@ class AWS1ClientTest extends AgentTestRunner {
}
}
}
span(1) {
operationName expectedOperationName(method)
spanKind CLIENT
errored false
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" "${server.address}${path}"
"$Tags.HTTP_METHOD" "$method"
"$Tags.HTTP_STATUS" 200
}
}
}
}
server.lastRequest.headers.get("traceparent") == null
@ -236,10 +220,10 @@ class AWS1ClientTest extends AgentTestRunner {
thrown SdkClientException
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -257,19 +241,6 @@ class AWS1ClientTest extends AgentTestRunner {
errorTags SdkClientException, ~/Unable to execute HTTP request/
}
}
span(1) {
operationName expectedOperationName(method)
spanKind CLIENT
errored true
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" UNUSABLE_PORT
"$Tags.HTTP_URL" "http://localhost:${UNUSABLE_PORT}/$url"
"$Tags.HTTP_METHOD" "$method"
errorTags HttpHostConnectException, ~/Connection refused/
}
}
}
}
@ -298,7 +269,7 @@ class AWS1ClientTest extends AgentTestRunner {
trace(0, 1) {
span(0) {
operationName "S3.HeadBucket"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -316,7 +287,8 @@ class AWS1ClientTest extends AgentTestRunner {
}
}
def "timeout and retry errors captured"() {
// TODO(anuraaga): Add events for retries.
def "timeout and retry errors not captured"() {
setup:
def server = httpServer {
handlers {
@ -337,10 +309,10 @@ class AWS1ClientTest extends AgentTestRunner {
thrown AmazonClientException
assertTraces(1) {
trace(0, 5) {
trace(0, 1) {
span(0) {
operationName "S3.GetObject"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -360,29 +332,6 @@ class AWS1ClientTest extends AgentTestRunner {
}
}
}
(1..4).each {
span(it) {
operationName expectedOperationName("GET")
spanKind CLIENT
errored true
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" "$server.address/someBucket/someKey"
"$Tags.HTTP_METHOD" "GET"
try {
errorTags SocketException, "Socket closed"
} catch (AssertionError e) {
try {
errorTags SocketException, "Socket Closed" // windows
} catch (AssertionError f) {
errorTags RequestAbortedException, "Request aborted"
}
}
}
}
}
}
}

View File

@ -34,8 +34,6 @@ import io.opentelemetry.auto.bootstrap.instrumentation.decorator.HttpClientDecor
import io.opentelemetry.auto.instrumentation.api.MoreTags
import io.opentelemetry.auto.instrumentation.api.Tags
import io.opentelemetry.auto.test.AgentTestRunner
import org.apache.http.conn.HttpHostConnectException
import org.apache.http.impl.execchain.RequestAbortedException
import spock.lang.AutoCleanup
import spock.lang.Shared
@ -44,7 +42,6 @@ import java.util.concurrent.atomic.AtomicReference
import static io.opentelemetry.auto.test.server.http.TestHttpServer.httpServer
import static io.opentelemetry.auto.test.utils.PortUtils.UNUSABLE_PORT
import static io.opentelemetry.trace.Span.Kind.CLIENT
import static io.opentelemetry.trace.Span.Kind.INTERNAL
class AWS0ClientTest extends AgentTestRunner {
@ -112,10 +109,10 @@ class AWS0ClientTest extends AgentTestRunner {
client.requestHandler2s.get(0).getClass().getSimpleName() == "TracingRequestHandler"
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored false
parent()
tags {
@ -133,19 +130,6 @@ class AWS0ClientTest extends AgentTestRunner {
}
}
}
span(1) {
operationName expectedOperationName(method)
spanKind CLIENT
errored false
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" "${server.address}${path}"
"$Tags.HTTP_METHOD" "$method"
"$Tags.HTTP_STATUS" 200
}
}
}
}
server.lastRequest.headers.get("traceparent") == null
@ -181,10 +165,10 @@ class AWS0ClientTest extends AgentTestRunner {
thrown AmazonClientException
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -202,19 +186,6 @@ class AWS0ClientTest extends AgentTestRunner {
errorTags AmazonClientException, ~/Unable to execute HTTP request/
}
}
span(1) {
operationName expectedOperationName(method)
spanKind CLIENT
errored true
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" UNUSABLE_PORT
"$Tags.HTTP_URL" "http://localhost:${UNUSABLE_PORT}/$url"
"$Tags.HTTP_METHOD" "$method"
errorTags HttpHostConnectException, ~/Connection refused/
}
}
}
}
@ -243,7 +214,7 @@ class AWS0ClientTest extends AgentTestRunner {
trace(0, 1) {
span(0) {
operationName "S3.GetObject"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -262,7 +233,8 @@ class AWS0ClientTest extends AgentTestRunner {
}
}
def "timeout and retry errors captured"() {
// TODO(anuraaga): Add events for retries.
def "timeout and retry errors not captured"() {
setup:
def server = httpServer {
handlers {
@ -283,10 +255,10 @@ class AWS0ClientTest extends AgentTestRunner {
thrown AmazonClientException
assertTraces(1) {
trace(0, 5) {
trace(0, 1) {
span(0) {
operationName "S3.GetObject"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -302,29 +274,6 @@ class AWS0ClientTest extends AgentTestRunner {
errorTags AmazonClientException, ~/Unable to execute HTTP request/
}
}
(1..4).each {
span(it) {
operationName expectedOperationName("GET")
spanKind CLIENT
errored true
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" "$server.address/someBucket/someKey"
"$Tags.HTTP_METHOD" "GET"
try {
errorTags SocketException, "Socket closed"
} catch (AssertionError e) {
try {
errorTags SocketException, "Socket Closed" // windows
} catch (AssertionError f) {
errorTags RequestAbortedException, "Request aborted"
}
}
}
}
}
}
}

View File

@ -16,13 +16,13 @@
package io.opentelemetry.auto.instrumentation.awssdk.v2_2;
import static io.opentelemetry.auto.bootstrap.WeakMap.Provider.newWeakMap;
import static io.opentelemetry.trace.TracingContextUtils.currentContextWith;
import io.opentelemetry.auto.bootstrap.WeakMap;
import io.opentelemetry.auto.bootstrap.instrumentation.decorator.ClientDecorator;
import io.opentelemetry.context.ContextUtils;
import io.opentelemetry.context.Scope;
import io.opentelemetry.instrumentation.awssdk.v2_2.AwsSdk;
import io.opentelemetry.trace.Span;
import io.opentelemetry.trace.Span.Kind;
import java.io.InputStream;
import java.nio.ByteBuffer;
import java.util.Optional;
@ -73,8 +73,7 @@ public class TracingExecutionInterceptor implements ExecutionInterceptor {
OVERRIDE_CONFIGURATION_CONSUMER =
builder ->
builder.addExecutionInterceptor(
// Agent will trace HTTP calls too so use INTERNAL kind.
new TracingExecutionInterceptor(AwsSdk.newInterceptor(Kind.INTERNAL)));
new TracingExecutionInterceptor(AwsSdk.newInterceptor()));
private final ExecutionInterceptor delegate;
@ -152,7 +151,8 @@ public class TracingExecutionInterceptor implements ExecutionInterceptor {
if (span != null) {
// This scope will be closed by AwsHttpClientInstrumentation since ExecutionInterceptor API
// doesn't provide a way to run code in the same thread after transmission has been scheduled.
ScopeHolder.CURRENT.set(currentContextWith(span));
ScopeHolder.CURRENT.set(
ContextUtils.withScopedContext(ClientDecorator.currentContextWith(span)));
}
}

View File

@ -51,7 +51,6 @@ import java.util.concurrent.atomic.AtomicReference
import static io.opentelemetry.auto.test.server.http.TestHttpServer.httpServer
import static io.opentelemetry.trace.Span.Kind.CLIENT
import static io.opentelemetry.trace.Span.Kind.INTERNAL
class Aws2ClientTest extends AgentTestRunner {
@ -90,10 +89,10 @@ class Aws2ClientTest extends AgentTestRunner {
response.class.simpleName.startsWith(operation) || response instanceof ResponseInputStream
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored false
parent()
tags {
@ -119,19 +118,6 @@ class Aws2ClientTest extends AgentTestRunner {
}
}
}
span(1) {
operationName expectedOperationName(method)
spanKind CLIENT
errored false
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" { it.startsWith("${server.address}${path}") }
"$Tags.HTTP_METHOD" "$method"
"$Tags.HTTP_STATUS" 200
}
}
}
}
server.lastRequest.headers.get("traceparent") == null
@ -193,7 +179,7 @@ class Aws2ClientTest extends AgentTestRunner {
trace(0, 1) {
span(0) {
operationName "$service.$operation"
spanKind INTERNAL
spanKind CLIENT
errored false
parent()
tags {
@ -294,9 +280,8 @@ class Aws2ClientTest extends AgentTestRunner {
then:
assertTraces(1) {
trace(0, 2) {
trace(0, 1) {
span(0) {}
span(1) {}
}
}
server.lastRequest.headers.get("x-name") == "value"
@ -305,7 +290,8 @@ class Aws2ClientTest extends AgentTestRunner {
server.close()
}
def "timeout and retry errors captured"() {
// TODO(anuraaga): Add events for retries.
def "timeout and retry errors not captured"() {
setup:
def server = httpServer {
handlers {
@ -329,10 +315,10 @@ class Aws2ClientTest extends AgentTestRunner {
thrown SdkClientException
assertTraces(1) {
trace(0, 5) {
trace(0, 1) {
span(0) {
operationName "S3.GetObject"
spanKind INTERNAL
spanKind CLIENT
errored true
parent()
tags {
@ -347,21 +333,6 @@ class Aws2ClientTest extends AgentTestRunner {
errorTags SdkClientException, "Unable to execute HTTP request: Read timed out"
}
}
(1..4).each {
span(it) {
operationName expectedOperationName("GET")
spanKind CLIENT
errored true
childOf span(0)
tags {
"$MoreTags.NET_PEER_NAME" "localhost"
"$MoreTags.NET_PEER_PORT" server.address.port
"$Tags.HTTP_URL" "$server.address/somebucket/somekey"
"$Tags.HTTP_METHOD" "GET"
errorTags SocketTimeoutException, "Read timed out"
}
}
}
}
}