From a88c32bc0671b147723670339406b9a4cd76b60c Mon Sep 17 00:00:00 2001 From: Robert Kruszewski Date: Thu, 18 Apr 2019 13:53:49 +0100 Subject: [PATCH 1/3] Correctly nest spans when tracing okhttp requests --- .../conjure/java/client/jaxrs/TracerTest.java | 52 +++++++++++-------- .../conjure/java/okhttp/AsyncTracerTag.java | 32 ++++++++++++ ...DispatcherTraceTerminatingInterceptor.java | 7 ++- .../conjure/java/okhttp/OkHttpClients.java | 3 +- .../java/okhttp/RemotingOkHttpCall.java | 12 ++++- .../java/okhttp/RemotingOkHttpClient.java | 2 +- 6 files changed, 78 insertions(+), 30 deletions(-) create mode 100644 okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/AsyncTracerTag.java diff --git a/conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java b/conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java index 17259ac73..b560b0e35 100644 --- a/conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java +++ b/conjure-java-jaxrs-client/src/test/java/com/palantir/conjure/java/client/jaxrs/TracerTest.java @@ -16,22 +16,17 @@ package com.palantir.conjure.java.client.jaxrs; -import static org.hamcrest.Matchers.contains; -import static org.hamcrest.Matchers.hasSize; -import static org.hamcrest.Matchers.is; -import static org.hamcrest.Matchers.not; -import static org.junit.Assert.assertThat; +import static org.assertj.core.api.Assertions.assertThat; import com.google.common.collect.Lists; -import com.google.common.collect.Maps; import com.google.common.collect.Sets; import com.palantir.conjure.java.okhttp.HostMetricsRegistry; import com.palantir.tracing.Tracer; import com.palantir.tracing.api.OpenSpan; +import com.palantir.tracing.api.Span; import com.palantir.tracing.api.SpanType; import com.palantir.tracing.api.TraceHttpHeaders; import java.util.List; -import java.util.Map; import java.util.Optional; import java.util.Set; import java.util.concurrent.CompletableFuture; @@ -61,25 +56,40 @@ public void before() { public void testClientIsInstrumentedWithTracer() throws InterruptedException { server.enqueue(new MockResponse().setBody("\"server\"")); OpenSpan parentTrace = Tracer.startSpan(""); - List> observedSpans = Lists.newArrayList(); - Tracer.subscribe(TracerTest.class.getName(), - span -> observedSpans.add(Maps.immutableEntry(span.type(), span.getOperation()))); + List observedSpans = Lists.newArrayList(); + Tracer.subscribe(TracerTest.class.getName(), observedSpans::add); String traceId = Tracer.getTraceId(); service.param("somevalue"); Tracer.unsubscribe(TracerTest.class.getName()); - assertThat(observedSpans, contains( - Maps.immutableEntry(SpanType.LOCAL, "OkHttp: acquire-limiter-enqueue"), - Maps.immutableEntry(SpanType.LOCAL, "OkHttp: acquire-limiter-run"), - Maps.immutableEntry(SpanType.LOCAL, "OkHttp: execute-enqueue"), - Maps.immutableEntry(SpanType.CLIENT_OUTGOING, "OkHttp: GET /{param}"), - Maps.immutableEntry(SpanType.LOCAL, "OkHttp: execute-run"), - Maps.immutableEntry(SpanType.LOCAL, "OkHttp: dispatcher"))); + Span executeRunSpan = observedSpans.stream() + .filter(s -> s.getOperation().equals("OkHttp: execute-run")) + .findFirst() + .get(); + + assertThat(observedSpans).allSatisfy(span -> { + if (span.getOperation().equals("OkHttp: GET /{param}")) { + assertThat(span.type()).isEqualTo(SpanType.CLIENT_OUTGOING); + assertThat(span.getParentSpanId().get()).isEqualTo(executeRunSpan.getSpanId()); + } else { + assertThat(span.type()).isEqualTo(SpanType.LOCAL); + assertThat(span.getParentSpanId().get()).isEqualTo(parentTrace.getSpanId()); + } + }); + assertThat(observedSpans) + .extracting(Span::getOperation) + .containsExactly( + "OkHttp: acquire-limiter-enqueue", + "OkHttp: acquire-limiter-run", + "ignored-span", + "OkHttp: execute-enqueue", + "OkHttp: GET /{param}", + "OkHttp: execute-run"); RecordedRequest request = server.takeRequest(); - assertThat(request.getHeader(TraceHttpHeaders.TRACE_ID), is(traceId)); - assertThat(request.getHeader(TraceHttpHeaders.SPAN_ID), is(not(parentTrace.getSpanId()))); + assertThat(request.getHeader(TraceHttpHeaders.TRACE_ID)).isEqualTo(traceId); + assertThat(request.getHeader(TraceHttpHeaders.SPAN_ID)).isNotEqualTo(parentTrace.getSpanId()); } @Test @@ -89,7 +99,7 @@ public void testLimiterAcquisitionMultiThread() { addTraceSubscriber(observedTraceIds); runTwoRequestsInParallel(); removeTraceSubscriber(); - assertThat(observedTraceIds, hasSize(2)); + assertThat(observedTraceIds).containsExactly("first", "second"); } private void runTwoRequestsInParallel() { @@ -130,7 +140,7 @@ private void reduceConcurrencyLimitTo1() { server.enqueue(new MockResponse().setResponseCode(429)); }); server.enqueue(new MockResponse().setBody("\"server\"")); - assertThat(service.string(), is("server")); + assertThat(service.string()).isEqualTo("server"); } } } diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/AsyncTracerTag.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/AsyncTracerTag.java new file mode 100644 index 000000000..bfa379844 --- /dev/null +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/AsyncTracerTag.java @@ -0,0 +1,32 @@ +/* + * (c) Copyright 2019 Palantir Technologies Inc. All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.palantir.conjure.java.okhttp; + +import com.palantir.conjure.java.client.config.ImmutablesStyle; +import com.palantir.tracing.AsyncTracer; +import org.immutables.value.Value; + +@Value.Modifiable +@ImmutablesStyle +public interface AsyncTracerTag { + AsyncTracer asyncTracer(); + AsyncTracerTag setAsyncTracer(AsyncTracer asyncTracer); + + static AsyncTracerTag create() { + return ModifiableAsyncTracerTag.create(); + } +} diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java index 28ee9a390..91879d8b1 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java @@ -16,7 +16,6 @@ package com.palantir.conjure.java.okhttp; -import com.palantir.tracing.AsyncTracer; import java.io.IOException; import okhttp3.Interceptor; import okhttp3.Response; @@ -24,11 +23,11 @@ public final class DispatcherTraceTerminatingInterceptor implements Interceptor { @Override public Response intercept(Chain chain) throws IOException { - AsyncTracer tracerTag = chain.request().tag(AsyncTracer.class); - if (tracerTag == null) { + AsyncTracerTag tracerTag = chain.request().tag(AsyncTracerTag.class); + if (tracerTag == null && tracerTag.asyncTracer() == null) { return chain.proceed(chain.request()); } - return tracerTag.withTrace(() -> chain.proceed(chain.request())); + return tracerTag.asyncTracer().withTrace(() -> chain.proceed(chain.request())); } } diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/OkHttpClients.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/OkHttpClients.java index d5cdb147a..3623838df 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/OkHttpClients.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/OkHttpClients.java @@ -81,8 +81,7 @@ public final class OkHttpClients { * * */ - private static final ExecutorService executionExecutor = - Tracers.wrap("OkHttp: dispatcher", Executors.newCachedThreadPool(executionThreads)); + private static final ExecutorService executionExecutor = Executors.newCachedThreadPool(executionThreads); /** Shared dispatcher with static executor service. */ private static final Dispatcher dispatcher; diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java index cba89975e..c8e9392f0 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpCall.java @@ -30,6 +30,7 @@ import com.palantir.logsafe.exceptions.SafeIllegalStateException; import com.palantir.logsafe.exceptions.SafeIoException; import com.palantir.tracing.AsyncTracer; +import com.palantir.tracing.Tracer; import java.io.IOException; import java.io.InterruptedIOException; import java.net.SocketTimeoutException; @@ -165,8 +166,15 @@ public void enqueue(Callback callback) { Futures.addCallback(limiterListener, new FutureCallback() { @Override public void onSuccess(Limiter.Listener listener) { - tracer.withTrace(() -> null); - enqueueInternal(callback); + tracer.withTrace(() -> { + // terminate acquire-limiter-run span + Tracer.fastCompleteSpan(); + request().tag(AsyncTracerTag.class).setAsyncTracer(new AsyncTracer("OkHttp: execute")); + enqueueInternal(callback); + // Need to recreate a span to make sure withTrace will not close parent spans + Tracer.startSpan("ignored-span"); + return null; + }); } @Override diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java index 0cfa4b2cf..27e58d781 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java @@ -102,7 +102,7 @@ private Request createNewRequest(Request request) { return request.newBuilder() .url(getNewRequestUrl(request.url())) .tag(ConcurrencyLimiterListener.class, ConcurrencyLimiterListener.create()) - .tag(AsyncTracer.class, new AsyncTracer("OkHttp: execute")) + .tag(AsyncTracerTag.class, AsyncTracerTag.create()) .build(); } From 49f243aad34029f8adb5c85ef1618af031410c16 Mon Sep 17 00:00:00 2001 From: Robert Kruszewski Date: Thu, 18 Apr 2019 13:58:04 +0100 Subject: [PATCH 2/3] imports --- .../com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java | 1 - 1 file changed, 1 deletion(-) diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java index 27e58d781..a1d31289c 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/RemotingOkHttpClient.java @@ -21,7 +21,6 @@ import com.palantir.logsafe.SafeArg; import com.palantir.logsafe.exceptions.SafeIllegalStateException; import com.palantir.logsafe.exceptions.SafeRuntimeException; -import com.palantir.tracing.AsyncTracer; import java.util.Optional; import java.util.concurrent.ExecutorService; import java.util.concurrent.ScheduledExecutorService; From ed3f6f396cf1ffd29564c7145e76054107f2d049 Mon Sep 17 00:00:00 2001 From: Robert Kruszewski Date: Thu, 18 Apr 2019 17:31:57 +0100 Subject: [PATCH 3/3] correct condition --- .../java/okhttp/DispatcherTraceTerminatingInterceptor.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java index 91879d8b1..b812aed72 100644 --- a/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java +++ b/okhttp-clients/src/main/java/com/palantir/conjure/java/okhttp/DispatcherTraceTerminatingInterceptor.java @@ -24,7 +24,7 @@ public final class DispatcherTraceTerminatingInterceptor implements Interceptor @Override public Response intercept(Chain chain) throws IOException { AsyncTracerTag tracerTag = chain.request().tag(AsyncTracerTag.class); - if (tracerTag == null && tracerTag.asyncTracer() == null) { + if (tracerTag == null || tracerTag.asyncTracer() == null) { return chain.proceed(chain.request()); }