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