From 7e215aac8245f2fb2e522e61ed21ab5dcfe7b830 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Mon, 6 Jun 2016 10:20:18 +0200 Subject: [PATCH] Added aspect that closes spans for wrong http responses (#296) 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 --- .../sleuth/instrument/web/TraceFilter.java | 9 ++- .../sleuth/instrument/web/TraceWebAspect.java | 20 ++++-- .../web/TraceFilterIntegrationTests.java | 70 +++++++++++++------ .../instrument/web/TraceFilterTests.java | 45 ++++++++---- .../instrument/web/client/WebClientTests.java | 59 ++++++++++++++++ .../src/test/resources/logback.xml | 11 +++ 6 files changed, 172 insertions(+), 42 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/test/resources/logback.xml diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java index e2bb7acf0..00b0d0b7f 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceFilter.java @@ -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())); } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAspect.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAspect.java index 16806edc7..6b39dd1f7 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAspect.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAspect.java @@ -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()); + } + } + } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java index 8f8e14337..10730ec1a 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java @@ -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 deferred() { - logger.info("deferred"); - this.tracer.addTag("tag", "value"); - span = this.tracer.getCurrentSpan(); - DeferredResult result = new DeferredResult<>(); - result.setResult("deferred"); - return result; - } + @RequestMapping("/deferred") + public DeferredResult deferred() { + logger.info("deferred"); + this.tracer.addTag("tag", "value"); + span = this.tracer.getCurrentSpan(); + DeferredResult result = new DeferredResult<>(); + result.setResult("deferred"); + return result; + } - @RequestMapping("/future") - public CompletableFuture future() { - logger.info("future"); - return CompletableFuture.completedFuture("ping"); + @RequestMapping("/future") + public CompletableFuture future() { + logger.info("future"); + return CompletableFuture.completedFuture("ping"); + } } @Configuration diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java index 2516dbc9e..b244a87b0 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java @@ -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() { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java index 56bbfd0c5..407fdee1a 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/WebClientTests.java @@ -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> 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 diff --git a/spring-cloud-sleuth-core/src/test/resources/logback.xml b/spring-cloud-sleuth-core/src/test/resources/logback.xml new file mode 100644 index 000000000..76eafe455 --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/resources/logback.xml @@ -0,0 +1,11 @@ + + + + + + + + + + + \ No newline at end of file