Added error tag upon exceptions (#435)

without this change there's no error colouring on Zipkin side
with this change we set error tags
- whenever there is an exception thrown on the server side (5xx)
- wheneber on the client side it's impossible to send a message

fixes #384
This commit is contained in:
Marcin Grzejszczak
2016-10-31 13:12:25 +01:00
committed by Marcin Grzejszczak
parent 067242288f
commit 5e5338869c
15 changed files with 145 additions and 68 deletions

View File

@@ -90,6 +90,7 @@ public class Span {
public static final String SPAN_NOT_SAMPLED = "0";
public static final String SPAN_LOCAL_COMPONENT_TAG_NAME = "lc";
public static final String SPAN_ERROR_TAG_NAME = "error";
/**
* <b>cr</b> - Client Receive. Signifies the end of the span. The client has

View File

@@ -23,6 +23,7 @@ import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.sampler.NeverSampler;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.messaging.Message;
import org.springframework.messaging.MessageChannel;
import org.springframework.messaging.MessageHandler;
@@ -53,6 +54,7 @@ public class TraceChannelInterceptor extends AbstractTraceChannelInterceptor {
} else if (spanFromHeader != null) {
spanFromHeader.logEvent(Span.CLIENT_RECV);
}
addErrorTag(ex);
getTracer().close(spanFromHeader);
}
@@ -120,10 +122,17 @@ public class TraceChannelInterceptor extends AbstractTraceChannelInterceptor {
Span spanFromHeader = getSpanFromHeader(message);
if (spanFromHeader!= null) {
spanFromHeader.logEvent(Span.SERVER_SEND);
addErrorTag(ex);
}
getTracer().detach(spanFromHeader);
}
private void addErrorTag(Exception ex) {
if (ex != null) {
getTracer().addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(ex));
}
}
private Span getSpanFromHeader(Message<?> message) {
if (message == null) {
return null;

View File

@@ -36,6 +36,7 @@ import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.sampler.NeverSampler;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.http.HttpStatus;
@@ -140,6 +141,7 @@ public class TraceFilter extends GenericFilterBean {
filterChain.doFilter(request, response);
} catch (Throwable e) {
exception = e;
this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e));
throw e;
} finally {
if (isAsyncStarted(request) || request.isAsyncStarted()) {

View File

@@ -27,6 +27,7 @@ import org.springframework.boot.autoconfigure.web.ErrorController;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.cloud.sleuth.util.SpanNameUtil;
import org.springframework.web.method.HandlerMethod;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;
@@ -150,6 +151,9 @@ public class TraceHandlerInterceptor extends HandlerInterceptorAdapter {
if (log.isDebugEnabled()) {
log.debug("Closing span " + span);
}
if (ex != null) {
getTracer().addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(ex));
}
getTracer().close(span);
}

View File

@@ -18,9 +18,11 @@ package org.springframework.cloud.sleuth.instrument.web.client;
import java.io.IOException;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.http.HttpRequest;
import org.springframework.http.client.ClientHttpRequestExecution;
import org.springframework.http.client.ClientHttpRequestInterceptor;
@@ -59,6 +61,7 @@ public class TraceRestTemplateInterceptor extends AbstractTraceHttpRequestInterc
if (log.isDebugEnabled()) {
log.debug("Exception occurred while trying to execute the request. Will close the span [" + currentSpan() + "]", e);
}
this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e));
this.tracer.close(currentSpan());
throw e;
}

View File

@@ -31,6 +31,7 @@ import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
import feign.Client;
import feign.Request;
import feign.Response;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
/**
* A Feign Client that closes a Span if there is no response body. In other cases Span
@@ -134,11 +135,7 @@ class TraceFeignClient implements Client {
private void logError(Exception e) {
Span span = getTracer().getCurrentSpan();
if (span != null) {
String message = e.getMessage() != null ? e.getMessage() : e.toString();
if (log.isDebugEnabled()) {
log.debug("Appending exception [" + message + "] to span " + span);
}
getTracer().addTag("error", message);
getTracer().addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e));
}
}

View File

@@ -55,4 +55,8 @@ public final class ExceptionUtils {
ExceptionUtils.fail = fail;
ExceptionUtils.lastException = null;
}
public static String getExceptionMessage(Throwable e) {
return e.getMessage() != null ? e.getMessage() : e.toString();
}
}

View File

@@ -71,27 +71,33 @@ public class Issue410Tests {
@Test
public void should_pass_tracing_info_for_tasks_running_without_a_pool() {
Span span = this.tracer.createSpan("foo");
try {
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/without_pool", String.class);
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/without_pool", String.class);
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
} finally {
this.tracer.close(span);
}
}
@Test
public void should_pass_tracing_info_for_tasks_running_with_a_pool() {
Span span = this.tracer.createSpan("foo");
try {
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/with_pool", String.class);
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/with_pool", String.class);
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
} finally {
this.tracer.close(span);
}
}
/**
@@ -100,14 +106,17 @@ public class Issue410Tests {
@Test
public void should_pass_tracing_info_for_completable_futures_with_executor() {
Span span = this.tracer.createSpan("foo");
try {
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/completable", String.class);
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/completable", String.class);
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
} finally {
this.tracer.close(span);
}
}
/**
@@ -116,14 +125,17 @@ public class Issue410Tests {
@Test
public void should_pass_tracing_info_for_completable_futures_with_task_scheduler() {
Span span = this.tracer.createSpan("foo");
try {
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/taskScheduler", String.class);
String response = this.restTemplate.getForObject("http://localhost:" + port() + "/taskScheduler", String.class);
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
then(response).isEqualTo(Span.idToHex(span.getTraceId()));
Awaitility.await().until(() -> {
then(this.asyncTask.getSpan().get()).isNotNull();
then(this.asyncTask.getSpan().get().getTraceId()).isEqualTo(span.getTraceId());
});
} finally {
this.tracer.close(span);
}
}
private int port() {

View File

@@ -35,6 +35,7 @@ import org.springframework.boot.test.context.SpringBootTest.WebEnvironment;
import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.assertions.ListOfSpans;
import org.springframework.cloud.sleuth.assertions.SleuthAssertions;
import org.springframework.cloud.sleuth.instrument.messaging.TraceChannelInterceptorTests.App;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
@@ -88,7 +89,7 @@ public class TraceChannelInterceptorTests implements MessageHandler {
this.message = message;
this.span = TestSpanContextHolder.getCurrentSpan();
if (message.getHeaders().containsKey("THROW_EXCEPTION")) {
throw new RuntimeException();
throw new RuntimeException("A terrible exception has occurred");
}
}
@@ -269,6 +270,9 @@ public class TraceChannelInterceptorTests implements MessageHandler {
then(this.message).isNotNull();
this.tracer.close(span);
then(TestSpanContextHolder.getCurrentSpan()).isNull();
then(new ListOfSpans(this.accumulator.getSpans()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
"A terrible exception has occurred");
}
@Test

View File

@@ -33,6 +33,7 @@ import org.springframework.cloud.sleuth.SpanExtractor;
import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.assertions.ListOfSpans;
import org.springframework.cloud.sleuth.log.SpanLogger;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.sampler.NeverSampler;
@@ -287,7 +288,7 @@ public class TraceFilterTests {
}
@Test
public void catchesException() throws Exception {
public void shouldAnnotateSpanWithErrorWhenExceptionIsThrown() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, this.spanReporter,
@@ -298,7 +299,7 @@ public class TraceFilterTests {
javax.servlet.ServletResponse response)
throws java.io.IOException, javax.servlet.ServletException {
throw new RuntimeException("Planned");
};
}
};
try {
filter.doFilter(this.request, this.response, this.filterChain);
@@ -309,6 +310,8 @@ public class TraceFilterTests {
verifyParentSpanHttpTags(HttpStatus.INTERNAL_SERVER_ERROR);
then(TestSpanContextHolder.getCurrentSpan()).isNull();
then(new ListOfSpans(this.spanReporter.getSpans()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME, "Planned");
}
@Test

View File

@@ -26,6 +26,7 @@ import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.assertions.ListOfSpans;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
@@ -73,6 +74,9 @@ public class TraceFilterWebIntegrationTests {
.doesNotHaveASpanWithName("error")
.hasASpanWithTagEqualTo("http.status_code", "500");
then(ExceptionUtils.getLastException()).isNull();
then(new ListOfSpans(this.accumulator.getSpans()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
"Request processing failed; nested exception is java.lang.RuntimeException: Throwing exception");
}
private int port() {

View File

@@ -27,15 +27,16 @@ import org.junit.Before;
import org.junit.Rule;
import org.junit.Test;
import org.springframework.cloud.sleuth.DefaultSpanNamer;
import org.springframework.cloud.sleuth.NoOpSpanReporter;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.assertions.ListOfSpans;
import org.springframework.cloud.sleuth.assertions.SleuthAssertions;
import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector;
import org.springframework.cloud.sleuth.log.NoOpSpanLogger;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.trace.DefaultTracer;
import org.springframework.cloud.sleuth.trace.TestSpanContextHolder;
import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.http.client.ClientHttpRequestFactory;
import org.springframework.http.client.ClientHttpRequestInterceptor;
@@ -59,10 +60,12 @@ public class TraceRestTemplateInterceptorIntegrationTests {
private DefaultTracer tracer;
private ArrayListSpanAccumulator spanAccumulator = new ArrayListSpanAccumulator();
@Before
public void setup() {
this.tracer = new DefaultTracer(new AlwaysSampler(), new Random(),
new DefaultSpanNamer(), new NoOpSpanLogger(), new NoOpSpanReporter());
new DefaultSpanNamer(), new NoOpSpanLogger(), this.spanAccumulator);
this.template.setInterceptors(Arrays.<ClientHttpRequestInterceptor>asList(
new TraceRestTemplateInterceptor(this.tracer, new HttpRequestInjector(),
new HttpTraceKeysInjector(this.tracer, new TraceKeys()))));
@@ -91,6 +94,9 @@ public class TraceRestTemplateInterceptorIntegrationTests {
SleuthAssertions.then(this.tracer.getCurrentSpan()).isEqualTo(span);
this.tracer.close(span);
SleuthAssertions.then(new ListOfSpans(this.spanAccumulator.getSpans()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
"Read timed out");
then(ExceptionUtils.getLastException()).isNull();
}

View File

@@ -99,7 +99,7 @@ public class TraceFeignClientTests {
then(this.tracer.getCurrentSpan()).isEqualTo(span);
then(this.spanAccumulator.getSpans().get(0))
.hasNotLoggedAnEvent(Span.CLIENT_RECV)
.hasATag("error", "exception has occurred");
.hasATag(Span.SPAN_ERROR_TAG_NAME, "exception has occurred");
}
}

View File

@@ -38,6 +38,7 @@ import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.assertions.ListOfSpans;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.context.annotation.Bean;
@@ -53,6 +54,7 @@ import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.RestTemplate;
import com.jayway.awaitility.Awaitility;
import com.netflix.hystrix.exception.HystrixRuntimeException;
import com.netflix.loadbalancer.BaseLoadBalancer;
import com.netflix.loadbalancer.ILoadBalancer;
@@ -61,7 +63,7 @@ import com.netflix.loadbalancer.Server;
import feign.codec.Decoder;
import feign.codec.ErrorDecoder;
import static org.assertj.core.api.BDDAssertions.then;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
/**
* Related to https://github.com/spring-cloud/spring-cloud-sleuth/issues/257
@@ -76,10 +78,12 @@ public class FeignClientServerErrorTests {
@Autowired TestFeignInterface feignInterface;
@Autowired TestFeignWithCustomConfInterface customConfFeignInterface;
@Autowired Listener listener;
@Rule public OutputCapture capture = new OutputCapture();
@Before
public void setup() {
this.listener.clear();
ExceptionUtils.setFail(true);
}
@@ -90,11 +94,17 @@ public class FeignClientServerErrorTests {
} catch (HystrixRuntimeException e) {
}
// ugly :/ waiting for rx thread to complete
Thread.sleep(100);
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
Awaitility.await().until(() -> {
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
then(new ListOfSpans(this.listener.getEvents()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
"Request processing failed; nested exception is java.lang.RuntimeException: Internal Error");
then(new ListOfSpans(this.listener.getEvents()))
.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
"Internal Error");
});
}
@Test
@@ -104,11 +114,11 @@ public class FeignClientServerErrorTests {
} catch (HystrixRuntimeException e) {
}
// ugly :/ waiting for rx thread to complete
Thread.sleep(100);
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
Awaitility.await().until(() -> {
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
});
}
@Test
@@ -118,11 +128,10 @@ public class FeignClientServerErrorTests {
} catch (HystrixRuntimeException e) {
}
// ugly :/ waiting for rx thread to complete
Thread.sleep(100);
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
Awaitility.await().until(() -> {
then(this.capture.toString()).doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
});
}
@Test
@@ -132,11 +141,10 @@ public class FeignClientServerErrorTests {
} catch (HystrixRuntimeException e) {
}
// ugly :/ waiting for rx thread to complete
Thread.sleep(100);
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
Awaitility.await().until(() -> {
then(this.capture.toString()).doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
});
}
@Test
@@ -146,11 +154,10 @@ public class FeignClientServerErrorTests {
} catch (HystrixRuntimeException e) {
}
// ugly :/ waiting for rx thread to complete
Thread.sleep(100);
then(this.capture.toString())
.doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
Awaitility.await().until(() -> {
then(this.capture.toString()).doesNotContain("Tried to close span but it is not the current span");
then(ExceptionUtils.getLastException()).isNull();
});
}
@Configuration
@@ -226,7 +233,11 @@ public class FeignClientServerErrorTests {
private List<Span> events = new ArrayList<>();
public List<Span> getEvents() {
return this.events;
return new ArrayList<>(this.events);
}
public void clear() {
this.events.clear();
}
@Override
@@ -246,8 +257,7 @@ public class FeignClientServerErrorTests {
@RequestHeader(Span.TRACE_ID_NAME) String traceId,
@RequestHeader(Span.SPAN_ID_NAME) String spanId,
@RequestHeader(Span.PARENT_ID_NAME) String parentId) {
return new ResponseEntity<>("internal error",
HttpStatus.INTERNAL_SERVER_ERROR);
throw new RuntimeException("Internal Error");
}
@RequestMapping("/notfound")

View File

@@ -50,4 +50,22 @@ public class ExceptionUtilsTest {
then(e).isInstanceOf(IllegalStateException.class);
}
}
@Test
public void should_print_error_message_when_there_is_one() throws Exception {
Throwable e = new RuntimeException("Foo");
String message = ExceptionUtils.getExceptionMessage(e);
then(message).isEqualTo("Foo");
}
@Test
public void should_print_to_string_when_there_is_no_error() throws Exception {
Throwable e = new RuntimeException();
String message = ExceptionUtils.getExceptionMessage(e);
then(message).isEqualTo("java.lang.RuntimeException");
}
}