Feign fixes

it turned out that some of the tests were leaky and didn't catch that ExceptionUtils were throwing an exception (race condition with Hystrix). That was due to the fact that When Hystrix with Feign were doing retries the RequestInterceptor wasn't called. That means that a new span wasn't created but a parent span was closed.

With this change the only place where the span creation and closing takes place is TraceFeignClient. I removed the Feign RequestInterceptor. Now whenever there is a retry - a new span is created and closed after getting a response. There are no exceptions, special cases etc.

In addition to that since Feign is fully immutable and SpanInjector is by design made to mutate objects I had to wrap the immutable Request in an AtomicReference in order to change the contents of the Request. I'm ashamed but didn't have a better idea. Since that is packaged scope nobody should every see that (outside the package of course)
This commit is contained in:
Marcin Grzejszczak
2016-09-08 22:06:44 +02:00
parent ef2445090d
commit 9e01d77431
14 changed files with 176 additions and 181 deletions

View File

@@ -146,6 +146,12 @@
<artifactId>spring-cloud-starter-eureka</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>com.github.stefanbirkner</groupId>
<artifactId>system-rules</artifactId>
<version>1.16.0</version>
<scope>test</scope>
</dependency>
</dependencies>
</project>

View File

@@ -16,14 +16,9 @@
package org.springframework.cloud.sleuth.instrument.hystrix;
import java.lang.invoke.MethodHandles;
import java.util.concurrent.Callable;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import com.netflix.hystrix.strategy.HystrixPlugins;
import com.netflix.hystrix.strategy.concurrency.HystrixConcurrencyStrategy;
import com.netflix.hystrix.strategy.eventnotifier.HystrixEventNotifier;
@@ -31,6 +26,12 @@ import com.netflix.hystrix.strategy.executionhook.HystrixCommandExecutionHook;
import com.netflix.hystrix.strategy.metrics.HystrixMetricsPublisher;
import com.netflix.hystrix.strategy.properties.HystrixPropertiesStrategy;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
/**
* A {@link HystrixConcurrencyStrategy} that wraps a {@link Callable} in a
* {@link Callable} that either starts a new span or continues one if the tracing was
@@ -109,6 +110,8 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy
// Visible for testing
static class HystrixTraceCallable<S> implements Callable<S> {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
private Tracer tracer;
private TraceKeys traceKeys;
private Callable<S> callable;
@@ -128,10 +131,16 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy
boolean created = false;
if (span != null) {
span = this.tracer.continueSpan(span);
if (log.isDebugEnabled()) {
log.debug("Continuing span " + span);
}
}
else {
span = this.tracer.createSpan(HYSTRIX_COMPONENT);
created = true;
if (log.isDebugEnabled()) {
log.debug("Creating new span " + span);
}
}
if (!span.tags().containsKey(Span.SPAN_LOCAL_COMPONENT_TAG_NAME)) {
this.tracer.addTag(Span.SPAN_LOCAL_COMPONENT_TAG_NAME, HYSTRIX_COMPONENT);
@@ -146,9 +155,15 @@ public class SleuthHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy
}
finally {
if (created) {
if (log.isDebugEnabled()) {
log.debug("Closing span since it was created" + span);
}
this.tracer.close(span);
}
else {
if (log.isDebugEnabled()) {
log.debug("Detaching span since it was continued " + span);
}
this.tracer.detach(span);
}
}

View File

@@ -241,7 +241,7 @@ public class TraceFilter extends GenericFilterBean {
}
if (parent.isRemote()) {
if (log.isDebugEnabled()) {
log.debug("Sending the parent span " + parent + " to Zipkin");
log.debug("Trying to send the parent span " + parent + " to Zipkin");
}
parent.stop();
parent.logEvent(Span.SERVER_SEND);

View File

@@ -0,0 +1,79 @@
/*
* Copyright 2013-2016 the original author or authors.
*
* 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 org.springframework.cloud.sleuth.instrument.web.client.feign;
import java.nio.charset.Charset;
import java.util.ArrayList;
import java.util.Collection;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.concurrent.atomic.AtomicReference;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.util.StringUtils;
import feign.Request;
/**
* Span injector that injects tracing info to {@link Request} via {@link AtomicReference}
* since {@link Request} is immutable.
*
* @author Marcin Grzejszczak
*
* @since 1.0.0
*/
class FeignRequestInjector implements SpanInjector<AtomicReference<Request>> {
@Override
public void inject(Span span, AtomicReference<Request> carrier) {
String method = carrier.get().method();
String url = carrier.get().url();
Map<String, Collection<String>> headers = new HashMap<>(carrier.get().headers());
byte[] body = carrier.get().body();
Charset charset = carrier.get().charset();
if (span == null) {
setHeader(headers, Span.SAMPLED_NAME, Span.SPAN_NOT_SAMPLED);
carrier.set(Request.create(method, url, headers, body, charset));
return;
}
setHeader(headers, Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId()));
setHeader(headers, Span.SPAN_NAME_NAME, span.getName());
setHeader(headers, Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
setHeader(headers, Span.SAMPLED_NAME, span.isExportable() ?
Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED);
Long parentId = getParentId(span);
if (parentId != null) {
setHeader(headers, Span.PARENT_ID_NAME, Span.idToHex(parentId));
}
setHeader(headers, Span.PROCESS_ID_NAME, span.getProcessId());
carrier.set(Request.create(method, url, headers, body, charset));
}
private Long getParentId(Span span) {
return !span.getParents().isEmpty() ? span.getParents().get(0) : null;
}
protected void setHeader(Map<String, Collection<String>> headers, String name, String value) {
if (StringUtils.hasText(value) && !headers.containsKey(name)) {
List<String> list = new ArrayList<>();
list.add(value);
headers.put(name, list);
}
}
}

View File

@@ -1,61 +0,0 @@
/*
* Copyright 2013-2016 the original author or authors.
*
* 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 org.springframework.cloud.sleuth.instrument.web.client.feign;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.util.StringUtils;
import feign.RequestTemplate;
/**
* Span injector that injects tracing info to {@link RequestTemplate}
*
* @author Marcin Grzejszczak
*
* @since 1.0.0
*/
class FeignRequestTemplateInjector implements SpanInjector<RequestTemplate> {
@Override
public void inject(Span span, RequestTemplate carrier) {
if (span == null) {
setHeader(carrier, Span.SAMPLED_NAME, Span.SPAN_NOT_SAMPLED);
return;
}
carrier.header(Span.TRACE_ID_NAME, Span.idToHex(span.getTraceId()));
setHeader(carrier, Span.SPAN_NAME_NAME, span.getName());
setHeader(carrier, Span.SPAN_ID_NAME, Span.idToHex(span.getSpanId()));
setHeader(carrier, Span.SAMPLED_NAME, span.isExportable() ?
Span.SPAN_SAMPLED : Span.SPAN_NOT_SAMPLED);
Long parentId = getParentId(span);
if (parentId != null) {
setHeader(carrier, Span.PARENT_ID_NAME, Span.idToHex(parentId));
}
setHeader(carrier, Span.PROCESS_ID_NAME, span.getProcessId());
}
private Long getParentId(Span span) {
return !span.getParents().isEmpty() ? span.getParents().get(0) : null;
}
protected void setHeader(RequestTemplate request, String name, String value) {
if (StringUtils.hasText(value) && !request.headers().containsKey(name)) {
request.header(name, value);
}
}
}

View File

@@ -19,6 +19,7 @@ package org.springframework.cloud.sleuth.instrument.web.client.feign;
import java.io.IOException;
import java.lang.invoke.MethodHandles;
import java.net.URI;
import java.util.concurrent.atomic.AtomicReference;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
@@ -39,7 +40,7 @@ import feign.Response;
*
* @since 1.0.0
*/
final class TraceFeignClient implements Client {
class TraceFeignClient implements Client {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
@@ -47,6 +48,7 @@ final class TraceFeignClient implements Client {
private HttpTraceKeysInjector keysInjector;
private final BeanFactory beanFactory;
private Tracer tracer;
private final FeignRequestInjector spanInjector = new FeignRequestInjector();
TraceFeignClient(BeanFactory beanFactory) {
this.beanFactory = beanFactory;
@@ -60,19 +62,40 @@ final class TraceFeignClient implements Client {
@Override
public Response execute(Request request, Request.Options options) throws IOException {
String spanName = getSpanName(request);
Span span = getTracer().createSpan(spanName);
if (log.isDebugEnabled()) {
log.debug("Created new Feign span " + span);
}
try {
AtomicReference<Request> feignRequest = new AtomicReference<>(request);
this.spanInjector.inject(span, feignRequest);
span.logEvent(Span.CLIENT_SEND);
addRequestTags(request);
Response response = this.delegate.execute(request, options);
Request modifiedRequest = feignRequest.get();
if (log.isDebugEnabled()) {
log.debug("The modified request equals " + modifiedRequest);
}
Response response = this.delegate.execute(modifiedRequest, options);
logCr();
return response;
} catch (RuntimeException | IOException e) {
logError(e);
throw e;
} finally {
closeSpan();
closeSpan(span);
}
}
private String getSpanName(Request request) {
URI uri = URI.create(request.url());
return uriScheme(uri) + ":" + uri.getPath();
}
private String uriScheme(URI uri) {
return uri.getScheme() == null ? "http" : uri.getScheme();
}
/**
* Adds HTTP tags to the client side span
*/
@@ -89,8 +112,7 @@ final class TraceFeignClient implements Client {
return this.keysInjector;
}
private void closeSpan() {
Span span = getTracer().getCurrentSpan();
private void closeSpan(Span span) {
if (span != null) {
if (log.isDebugEnabled()) {
log.debug("Closing Feign span " + span);
@@ -103,7 +125,7 @@ final class TraceFeignClient implements Client {
Span span = getTracer().getCurrentSpan();
if (span != null) {
if (log.isDebugEnabled()) {
log.debug("Closing Feign span and logging CR" + span);
log.debug("Closing Feign span and logging CR " + span);
}
span.logEvent(Span.CLIENT_RECV);
}

View File

@@ -32,7 +32,6 @@ import org.springframework.context.annotation.Scope;
import feign.Client;
import feign.Feign;
import feign.RequestInterceptor;
/**
* {@link org.springframework.boot.autoconfigure.EnableAutoConfiguration
@@ -84,13 +83,4 @@ public class TraceFeignClientAutoConfiguration {
TraceFeignObjectWrapper traceFeignObjectWrapper(BeanFactory beanFactory) {
return new TraceFeignObjectWrapper(beanFactory);
}
/**
* Sleuth {@link feign.RequestInterceptor} that either starts a new Span or continues
* an existing one if a retry takes place.
*/
@Bean
RequestInterceptor traceIdRequestInterceptor(Tracer tracer) {
return new TraceFeignRequestInterceptor(tracer, new FeignRequestTemplateInjector());
}
}

View File

@@ -1,63 +0,0 @@
/*
* Copyright 2013-2016 the original author or authors.
*
* 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 org.springframework.cloud.sleuth.instrument.web.client.feign;
import java.net.URI;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.cloud.sleuth.Tracer;
import feign.RequestInterceptor;
import feign.RequestTemplate;
/**
* A request interceptor that sets tracing information in the headers.
*
* @author Marcin Grzejszczak
*
* @since 1.0.0
*/
final class TraceFeignRequestInterceptor implements RequestInterceptor {
private final Tracer tracer;
private final SpanInjector<RequestTemplate> spanInjector;
TraceFeignRequestInterceptor(Tracer tracer,
SpanInjector<RequestTemplate> spanInjector) {
this.tracer = tracer;
this.spanInjector = spanInjector;
}
@Override
public void apply(RequestTemplate template) {
String spanName = getSpanName(template);
Span span = this.tracer.createSpan(spanName);
this.spanInjector.inject(span, template);
span.logEvent(Span.CLIENT_SEND);
}
private String getSpanName(RequestTemplate template) {
URI uri = URI.create(template.url());
return uriScheme(uri) + ":" + uri.getPath();
}
private String uriScheme(URI uri) {
return uri.getScheme() == null ? "http" : uri.getScheme();
}
}

View File

@@ -2,7 +2,6 @@ package org.springframework.cloud.sleuth.instrument.web.client.feign;
import java.io.IOException;
import java.lang.invoke.MethodHandles;
import java.util.Objects;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
@@ -10,7 +9,6 @@ import org.springframework.beans.factory.BeanFactory;
import org.springframework.cloud.netflix.feign.ribbon.CachingSpringLoadBalancerFactory;
import org.springframework.cloud.netflix.feign.ribbon.LoadBalancerFeignClient;
import org.springframework.cloud.netflix.ribbon.SpringClientFactory;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Tracer;
import feign.Client;
@@ -40,23 +38,7 @@ class TraceLoadBalancerFeignClient extends LoadBalancerFeignClient {
@Override public Response execute(Request request, Request.Options options)
throws IOException {
Span currentSpan = tracer().getCurrentSpan();
if (log.isDebugEnabled()) {
log.debug("Current span is " + currentSpan);
}
try {
return super.execute(request, options);
} catch (Exception e) {
if (Objects.equals(currentSpan, tracer().getCurrentSpan())) {
if (log.isDebugEnabled()) {
log.debug("Closing span " + currentSpan + " due to exception which is "
+ "not handled by Feign. This can happen when the load balancer "
+ "threw exception before Feign even managed to do sth about it");
}
tracer().close(currentSpan);
}
throw e;
}
return super.execute(request, options);
}
private static Client wrap(Client delegate, BeanFactory beanFactory) {

View File

@@ -17,6 +17,7 @@
package org.springframework.cloud.sleuth.instrument.web.client.exception;
import java.io.IOException;
import java.lang.invoke.MethodHandles;
import java.util.Collections;
import java.util.Map;
@@ -24,12 +25,16 @@ import com.netflix.loadbalancer.BaseLoadBalancer;
import com.netflix.loadbalancer.ILoadBalancer;
import com.netflix.loadbalancer.Server;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.junit.After;
import org.junit.Assert;
import org.junit.Before;
import org.junit.ClassRule;
import org.junit.Rule;
import org.junit.Test;
import org.junit.contrib.java.lang.system.SystemErrRule;
import org.junit.contrib.java.lang.system.SystemOutRule;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
@@ -68,10 +73,16 @@ import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
"spring.application.name=exceptionservice" }, randomPort = true)
public class WebClientExceptionTests {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
@ClassRule
public static final SpringClassRule SCR = new SpringClassRule();
@Rule
public final SpringMethodRule springMethodRule = new SpringMethodRule();
@Rule
public final SystemErrRule systemErrRule = new SystemErrRule().enableLog();
@Rule
public final SystemOutRule systemOutRule = new SystemOutRule().enableLog();
@Autowired TestFeignInterfaceWithException testFeignInterfaceWithException;
@Autowired @LoadBalanced RestTemplate template;
@@ -85,7 +96,6 @@ public class WebClientExceptionTests {
@After
public void close() {
ExceptionUtils.setFail(false);
TestSpanContextHolder.removeCurrentSpan();
}
@@ -95,6 +105,7 @@ public class WebClientExceptionTests {
public void shouldCloseSpanUponException(ResponseEntityProvider provider)
throws IOException {
Span span = this.tracer.createSpan("new trace");
log.info("Started new span " + span);
try {
provider.get(this);
@@ -107,6 +118,9 @@ public class WebClientExceptionTests {
then(ExceptionUtils.getLastException()).isNull();
then(this.tracer.getCurrentSpan()).isEqualTo(span);
this.tracer.close(span);
then(ExceptionUtils.getLastException()).isNull();
then(this.systemErrRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span");
then(this.systemOutRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span");
}
Object[] parametersForShouldCloseSpanUponException() {

View File

@@ -46,7 +46,7 @@ import org.springframework.cloud.sleuth.util.ExceptionUtils;
import feign.Client;
import feign.Feign;
import feign.FeignException;
import feign.RequestInterceptor;
import feign.Request;
import feign.RequestLine;
import feign.Response;
import okhttp3.mockwebserver.MockWebServer;
@@ -68,8 +68,6 @@ public class FeignRetriesTests {
ArrayListSpanAccumulator spanAccumulator = new ArrayListSpanAccumulator();
Tracer tracer = new DefaultTracer(new AlwaysSampler(), new Random(), new DefaultSpanNamer(),
new NoOpSpanLogger(), this.spanAccumulator);
FeignRequestTemplateInjector injector = new FeignRequestTemplateInjector();
TraceFeignRequestInterceptor interceptor = new TraceFeignRequestInterceptor(tracer, injector);
@Before
@After
@@ -91,7 +89,6 @@ public class FeignRetriesTests {
TestInterface api =
Feign.builder()
.client(new TraceFeignClient(beanFactory, client))
.requestInterceptor(interceptor)
.target(TestInterface.class, url);
try {
@@ -118,14 +115,15 @@ public class FeignRetriesTests {
"OK", Charset.defaultCharset());
}
};
RequestInterceptor requestInterceptor = template -> {
atomicInteger.incrementAndGet();
interceptor.apply(template);
};
TestInterface api =
Feign.builder()
.client(new TraceFeignClient(beanFactory, client))
.requestInterceptor(requestInterceptor)
.client(new TraceFeignClient(beanFactory, client) {
@Override public Response execute(Request request,
Request.Options options) throws IOException {
atomicInteger.incrementAndGet();
return super.execute(request, options);
}
})
.target(TestInterface.class, url);
then(api.decodedPost()).isEqualTo("OK");

View File

@@ -74,18 +74,18 @@ public class TraceFeignClientTests {
@Test
public void should_log_cr_when_response_successful() throws IOException {
this.tracer.createSpan("foo");
Span span = this.tracer.createSpan("foo");
Response response = this.traceFeignClient.execute(
Request.create("GET", "http://foo", new HashMap<>(), "".getBytes(),
Charset.defaultCharset()), new Request.Options());
then(this.tracer.getCurrentSpan()).isNull();
then(this.tracer.getCurrentSpan()).isEqualTo(span);
then(this.spanAccumulator.getSpans().get(0)).hasLoggedAnEvent(Span.CLIENT_RECV);
}
@Test
public void should_log_error_when_exception_thrown() throws IOException {
this.tracer.createSpan("foo");
Span span = this.tracer.createSpan("foo");
BDDMockito.given(this.client.execute(BDDMockito.any(), BDDMockito.any()))
.willThrow(new RuntimeException("exception has occurred"));
@@ -96,7 +96,7 @@ public class TraceFeignClientTests {
SleuthAssertions.fail("Exception should have been thrown");
} catch (Exception e) {}
then(this.tracer.getCurrentSpan()).isNull();
then(this.tracer.getCurrentSpan()).isEqualTo(span);
then(this.spanAccumulator.getSpans().get(0))
.hasNotLoggedAnEvent(Span.CLIENT_RECV)
.hasATag("error", "exception has occurred");

View File

@@ -16,12 +16,15 @@
package org.springframework.cloud.sleuth.stream;
import java.lang.invoke.MethodHandles;
import java.util.Iterator;
import java.util.LinkedList;
import java.util.List;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.metric.SpanMetricReporter;
@@ -38,6 +41,8 @@ import org.springframework.integration.annotation.Poller;
@MessageEndpoint
public class StreamSpanReporter implements SpanReporter {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
/**
* Bean name for the
* {@link org.springframework.integration.scheduling.PollerMetadata
@@ -79,6 +84,10 @@ public class StreamSpanReporter implements SpanReporter {
public void report(Span span) {
if (span.isExportable()) {
this.queue.add(span);
} else {
if (log.isDebugEnabled()) {
log.debug("The span " + span + " will not be sent to Zipkin due to sampling");
}
}
}
}

View File

@@ -204,6 +204,10 @@ public class ZipkinSpanListener implements SpanReporter {
public void report(Span span) {
if (span.isExportable()) {
this.reporter.report(convert(span));
} else {
if (log.isDebugEnabled()) {
log.debug("The span " + span + " will not be sent to Zipkin due to sampling");
}
}
}
}