SpringCloud/spring-cloud-sleuth
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Added aspect that closes spans for wrong http responses (#296)

Browse Source 
with this change trace filter is not closing all spans. It's closing only spans when the response is successful. If the response status is 4xx,5xx then an exception controller should start processing the response. At the end of the day an aspect will close the span once the controller has finished processing.

fixes #278
This commit is contained in:
Marcin Grzejszczak
2016-06-06 10:20:18 +02:00
parent 2b058be77e
commit 7e215aac82
6 changed files with 172 additions and 42 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java
View File

@@ -34,6 +34,7 @@ import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.sampler.NeverSampler;
import org.springframework.core.Ordered;
import org.springframework.core.annotation.Order;
import org.springframework.http.HttpStatus;
import org.springframework.util.StringUtils;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.UrlPathHelper;
@@ -147,7 +148,11 @@ public class TraceFilter extends OncePerRequestFilter {
} else {
spanFromRequest.logEvent(Span.SERVER_SEND);
}
this.tracer.close(spanFromRequest);
// in case of a response with exception status a exception controller will close the span
HttpStatus httpStatus = HttpStatus.valueOf(response.getStatus());
if (httpStatus.is2xxSuccessful() || httpStatus.is3xxRedirection()) {
this.tracer.close(spanFromRequest);
}
}
}
}
@@ -214,7 +219,7 @@ public class TraceFilter extends OncePerRequestFilter {
this.tracer.addTag(this.traceKeys.getHttp().getStatusCode(),
String.valueOf(HttpServletResponse.SC_INTERNAL_SERVER_ERROR));
}
else if ((httpStatus < 200) || (httpStatus > 299)) {
else if ((httpStatus < 200) || (httpStatus > 399)) {
this.tracer.addTag(this.traceKeys.getHttp().getStatusCode(),
String.valueOf(response.getStatus()));
}

20
spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAspect.java
View File

@@ -21,6 +21,7 @@ import java.util.concurrent.Callable;
import org.apache.commons.logging.Log;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
@@ -78,12 +79,13 @@ public class TraceWebAspect {
}
@Pointcut("@within(org.springframework.web.bind.annotation.RestController)")
private void anyRestControllerAnnotated() { // NOSONAR
}
private void anyRestControllerAnnotated() { }// NOSONAR
@Pointcut("@within(org.springframework.stereotype.Controller)")
private void anyControllerAnnotated() { // NOSONAR
}
private void anyControllerAnnotated() { } // NOSONAR
@Pointcut("target(org.springframework.boot.autoconfigure.web.ErrorController+)")
private void implementingErrorController() { } // NOSONAR
@Pointcut("execution(public java.util.concurrent.Callable *(..))")
private void anyPublicMethodReturningCallable() { } // NOSONAR
@@ -97,6 +99,9 @@ public class TraceWebAspect {
@Pointcut("(anyRestControllerAnnotated() || anyControllerAnnotated()) && anyPublicMethodReturningWebAsyncTask()")
private void anyControllerOrRestControllerWithPublicWebAsyncTaskMethod() { } // NOSONAR
@Pointcut("(anyRestControllerAnnotated() || anyControllerAnnotated()) && implementingErrorController()")
private void anyControllerOrRestControllerImplementingErrorController() { } // NOSONAR
@Around("anyControllerOrRestControllerWithPublicAsyncMethod()")
@SuppressWarnings("unchecked")
public Object wrapWithCorrelationId(ProceedingJoinPoint pjp) throws Throwable {
@@ -129,4 +134,11 @@ public class TraceWebAspect {
return webAsyncTask;
}
@After("anyControllerOrRestControllerImplementingErrorController()")
public void wrapErrorController() throws Throwable {
if (this.tracer.isTracing()) {
this.tracer.close(this.tracer.getCurrentSpan());
}
}
}

70
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java
View File

@@ -22,6 +22,7 @@ import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.http.HttpStatus;
import org.springframework.http.MediaType;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
import org.springframework.test.web.servlet.MvcResult;
@@ -109,6 +110,15 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
then(taggedSpan.get()).hasATag("tag", "value");
}
@Test
public void should_log_tracing_information_when_exception_was_thrown() throws Exception {
Long expectedTraceId = new Random().nextLong();
MvcResult mvcResult = whenSentToNonExistentEndpointWithTraceId(expectedTraceId);
then(tracingHeaderFrom(mvcResult)).isEqualTo(expectedTraceId);
}
@Override
protected void configureMockMvcBuilder(DefaultMockMvcBuilder mockMvcBuilder) {
mockMvcBuilder.addFilters(this.traceFilter);
@@ -137,6 +147,10 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
return sendDeferredWithTraceId(Span.TRACE_ID_NAME, passedTraceId);
}
private MvcResult whenSentToNonExistentEndpointWithTraceId(Long passedTraceId) throws Exception {
return sendRequestWithTraceId("/exception/nonExistent", Span.TRACE_ID_NAME, passedTraceId, HttpStatus.NOT_FOUND);
}
private MvcResult sendPingWithTraceId(String headerName, Long traceId)
throws Exception {
return sendRequestWithTraceId("/ping", headerName, traceId);
@@ -156,6 +170,16 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
.andReturn();
}
private MvcResult sendRequestWithTraceId(String path, String headerName, Long traceId, HttpStatus status)
throws Exception {
return this.mockMvc
.perform(MockMvcRequestBuilders.get(path).accept(MediaType.TEXT_PLAIN)
.header(headerName, Span.idToHex(traceId))
.header(Span.SPAN_ID_NAME, Span.idToHex(new Random().nextLong())))
.andExpect(status().is(status.value()))
.andReturn();
}
private Long tracingHeaderFrom(MvcResult mvcResult) {
return Span.hexToId(mvcResult.getResponse().getHeader(Span.TRACE_ID_NAME));
}
@@ -166,34 +190,36 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
}
@DefaultTestAutoConfiguration
@RestController
@Configuration
protected static class Config {
@Autowired
private Tracer tracer;
@RestController
public static class TestController {
@Autowired
private Tracer tracer;
@RequestMapping("/ping")
public String ping() {
logger.info("ping");
span = this.tracer.getCurrentSpan();
return "ping";
}
@RequestMapping("/ping")
public String ping() {
logger.info("ping");
span = this.tracer.getCurrentSpan();
return "ping";
}
@RequestMapping("/deferred")
public DeferredResult<String> deferred() {
logger.info("deferred");
this.tracer.addTag("tag", "value");
span = this.tracer.getCurrentSpan();
DeferredResult<String> result = new DeferredResult<>();
result.setResult("deferred");
return result;
}
@RequestMapping("/deferred")
public DeferredResult<String> deferred() {
logger.info("deferred");
this.tracer.addTag("tag", "value");
span = this.tracer.getCurrentSpan();
DeferredResult<String> result = new DeferredResult<>();
result.setResult("deferred");
return result;
}
@RequestMapping("/future")
public CompletableFuture<String> future() {
logger.info("future");
return CompletableFuture.completedFuture("ping");
@RequestMapping("/future")
public CompletableFuture<String> future() {
logger.info("future");
return CompletableFuture.completedFuture("ping");
}
}
@Configuration

45
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java
View File

@@ -22,6 +22,7 @@ import java.util.Optional;
import java.util.Random;
import java.util.regex.Pattern;
import org.junit.After;
import org.junit.Before;
import org.junit.Test;
import org.mockito.Mock;
@@ -47,12 +48,11 @@ import org.springframework.mock.web.MockHttpServletResponse;
import org.springframework.mock.web.MockServletContext;
import org.springframework.test.web.servlet.request.MockHttpServletRequestBuilder;
import static org.assertj.core.api.BDDAssertions.then;
import static org.junit.Assert.assertEquals;
import static org.mockito.MockitoAnnotations.initMocks;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.assertThat;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.entry;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertFalse;
import static org.junit.Assert.assertNull;
import static org.mockito.MockitoAnnotations.initMocks;
import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get;
/**
@@ -100,6 +100,11 @@ public class TraceFilterTests {
"MockMvc");
}
@After
public void cleanup() {
TestSpanContextHolder.removeCurrentSpan();
}
@Test
public void notTraced() throws Exception {
this.sampler = NeverSampler.INSTANCE;
@@ -111,8 +116,8 @@ public class TraceFilterTests {
filter.doFilter(this.request, this.response, this.filterChain);
assertFalse(this.span.isExportable());
assertNull(TestSpanContextHolder.getCurrentSpan());
then(this.span.isExportable()).isFalse();
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -123,7 +128,7 @@ public class TraceFilterTests {
verifyCurrentSpanStatusCode(HttpStatus.OK);
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -145,7 +150,7 @@ public class TraceFilterTests {
.hasATag("http.host", "localhost")
.hasATag("http.path", "/")
.hasATag("http.method", "GET");
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
private Span parentSpan() {
@@ -166,7 +171,7 @@ public class TraceFilterTests {
this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
filter.doFilter(this.request, this.response, this.filterChain);
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -180,7 +185,7 @@ public class TraceFilterTests {
verifyParentSpanHttpTags();
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -195,8 +200,7 @@ public class TraceFilterTests {
filter.doFilter(this.request, this.response, this.filterChain);
assertThat(parentSpan().tags()).contains(entry("http.x-foo", "bar"));
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -227,7 +231,7 @@ public class TraceFilterTests {
assertThat(parentSpan().tags()).contains(entry("http.x-foo", "'bar','spam'"));
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
@@ -252,7 +256,20 @@ public class TraceFilterTests {
}
verifyParentSpanHttpTags(HttpStatus.INTERNAL_SERVER_ERROR);
assertNull(TestSpanContextHolder.getCurrentSpan());
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
public void doesNotCloseSpanWhenResponseStatusIsNot2xx() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, this.spanReporter,
this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
this.response.setStatus(404);
filter.doFilter(this.request, this.response, this.filterChain);
then(TestSpanContextHolder.getCurrentSpan()).isNotNull();
}
public void verifyParentSpanHttpTags() {

59
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java
View File

@@ -16,6 +16,7 @@
package org.springframework.cloud.sleuth.instrument.web.client;
import javax.servlet.http.HttpServletRequest;
import java.util.ArrayList;
import java.util.Collections;
import java.util.HashMap;
@@ -36,6 +37,9 @@ import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
import org.springframework.boot.autoconfigure.web.BasicErrorController;
import org.springframework.boot.autoconfigure.web.ErrorAttributes;
import org.springframework.boot.autoconfigure.web.ServerProperties;
import org.springframework.boot.test.SpringApplicationConfiguration;
import org.springframework.boot.test.WebIntegrationTest;
import org.springframework.cloud.client.loadbalancer.LoadBalanced;
@@ -59,12 +63,14 @@ import org.springframework.web.bind.annotation.RequestHeader;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.HttpClientErrorException;
import org.springframework.web.client.RestTemplate;
import junitparams.JUnitParamsRunner;
import junitparams.Parameters;
import static junitparams.JUnitParamsRunner.$;
import static org.assertj.core.api.Assertions.fail;
import static org.assertj.core.api.BDDAssertions.then;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
@@ -80,11 +86,13 @@ public class WebClientTests {
@Autowired @LoadBalanced RestTemplate template;
@Autowired Listener listener;
@Autowired Tracer tracer;
@Autowired TestErrorController testErrorController;
@After
public void close() {
TestSpanContextHolder.removeCurrentSpan();
this.listener.getSpans().clear();
this.testErrorController.clear();
}
@Test
@@ -194,6 +202,25 @@ public class WebClientTests {
.getForEntity("http://fooservice/noresponse", String.class));
}
@Test
public void shouldCloseSpanWhenErrorControllerGetsCalled() {
try {
this.template.getForEntity("http://fooservice/nonExistent", String.class);
fail("An exception should be thrown");
} catch (HttpClientErrorException e) { }
then(this.tracer.getCurrentSpan()).isNull();
then(this.testErrorController.getSpan()).isNotNull();
}
@Test
public void shouldNotExecuteErrorControllerWhenUrlIsFound() {
this.template.getForEntity("http://fooservice/notrace", String.class);
then(this.tracer.getCurrentSpan()).isNull();
then(this.testErrorController.getSpan()).isNull();
}
private void thenRegisteredClientSentAndReceivedEvents(Span span) {
then(span).hasLoggedAnEvent(Span.CLIENT_RECV);
then(span).hasLoggedAnEvent(Span.CLIENT_SEND);
@@ -249,6 +276,38 @@ public class WebClientTests {
Sampler testSampler() {
return new AlwaysSampler();
}
@Bean
TestErrorController testErrorController(ErrorAttributes errorAttributes, Tracer tracer) {
return new TestErrorController(errorAttributes, tracer);
}
}
public static class TestErrorController extends BasicErrorController {
private final Tracer tracer;
Span span;
public TestErrorController(ErrorAttributes errorAttributes, Tracer tracer) {
super(errorAttributes, new ServerProperties().getError());
this.tracer = tracer;
}
@Override
public ResponseEntity<Map<String, Object>> error(HttpServletRequest request) {
this.span = this.tracer.getCurrentSpan();
return super.error(request);
}
public Span getSpan() {
return this.span;
}
public void clear() {
this.span = null;
}
}
@Component

11
spring-cloud-sleuth-core/src/test/resources/logback.xml Normal file
View File

@@ -0,0 +1,11 @@
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<logger name="org.springframework.cloud.sleuth" level="DEBUG"/>
<logger name="org.springframework.boot" level="DEBUG"/>
<logger name="org.springframework.web" level="DEBUG"/>
<root level="INFO">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
</root>
</configuration>