From e7b192575c99a08c779cd1df5a085dbf7d0dfe2c Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Mon, 8 May 2017 10:48:22 +0200 Subject: [PATCH] Added aspects around exception resolvers without this change any update on a span in custom exception resolver where ignored cause the span got detached in TraceFilter instead of it getting closed with this change we're adding an error tag if it was missing and we're also marking the span for closure by TraceFilter fixes #585 --- .../sleuth/instrument/web/TraceFilter.java | 18 ++ .../sleuth/instrument/web/TraceWebAspect.java | 35 ++++ .../web/TraceWebAutoConfiguration.java | 4 +- .../exceptionresolver/Issue585Tests.java | 171 ++++++++++++++++++ 4 files changed, 226 insertions(+), 2 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exceptionresolver/Issue585Tests.java 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 da980679f..a9692ebe2 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 @@ -86,6 +86,9 @@ public class TraceFilter extends GenericFilterBean { protected static final String TRACE_ERROR_HANDLED_REQUEST_ATTR = TraceFilter.class.getName() + ".ERROR_HANDLED"; + protected static final String TRACE_CLOSE_SPAN_REQUEST_ATTR = TraceFilter.class.getName() + + ".CLOSE_SPAN"; + /** * @deprecated please use {@link SleuthWebProperties#DEFAULT_SKIP_PATTERN} */ @@ -243,6 +246,12 @@ public class TraceFilter extends GenericFilterBean { log.debug( "Won't detach the span " + span + " since error has already been handled"); } + } else if (shouldCloseSpan(request) && this.tracer.isTracing() && stillTracingCurrentSapn(span)) { + if (log.isDebugEnabled()) { + log.debug( + "Will close span " + span + " since some component marked it for closure"); + } + this.tracer.close(span); } else if (this.tracer.isTracing()) { if (log.isDebugEnabled()) { log.debug("Detaching the span " + span + " since the response was unsuccessful"); @@ -252,6 +261,10 @@ public class TraceFilter extends GenericFilterBean { } } + private boolean stillTracingCurrentSapn(Span span) { + return this.tracer.getCurrentSpan().equals(span); + } + private void recordParentSpan(Span parent) { if (parent == null) { return; @@ -287,6 +300,11 @@ public class TraceFilter extends GenericFilterBean { String.valueOf(request.getAttribute(TRACE_ERROR_HANDLED_REQUEST_ATTR))); } + private boolean shouldCloseSpan(HttpServletRequest request) { + return Boolean.valueOf( + String.valueOf(request.getAttribute(TRACE_CLOSE_SPAN_REQUEST_ATTR))); + } + private boolean isSpanContinued(HttpServletRequest request) { return getSpanFromAttribute(request) != null; } 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 bcf842bd0..7e759d7fc 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 @@ -18,15 +18,21 @@ package org.springframework.cloud.sleuth.instrument.web; import java.lang.reflect.Field; import java.util.concurrent.Callable; +import javax.servlet.http.HttpServletRequest; +import javax.servlet.http.HttpServletResponse; import org.apache.commons.logging.Log; import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.annotation.Pointcut; +import org.springframework.cloud.sleuth.NoOpSpanReporter; +import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.SpanNamer; +import org.springframework.cloud.sleuth.SpanReporter; import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.instrument.async.TraceContinuingCallable; +import org.springframework.cloud.sleuth.util.ExceptionUtils; import org.springframework.web.context.request.async.WebAsyncTask; /** @@ -70,10 +76,19 @@ public class TraceWebAspect { private final Tracer tracer; private final SpanNamer spanNamer; + private final SpanReporter spanReporter; + @Deprecated public TraceWebAspect(Tracer tracer, SpanNamer spanNamer) { this.tracer = tracer; this.spanNamer = spanNamer; + this.spanReporter = new NoOpSpanReporter(); + } + + public TraceWebAspect(Tracer tracer, SpanNamer spanNamer, SpanReporter spanReporter) { + this.tracer = tracer; + this.spanNamer = spanNamer; + this.spanReporter = spanReporter; } @Pointcut("@within(org.springframework.web.bind.annotation.RestController)") @@ -91,6 +106,9 @@ public class TraceWebAspect { @Pointcut("execution(public org.springframework.web.context.request.async.WebAsyncTask *(..))") private void anyPublicMethodReturningWebAsyncTask() { } // NOSONAR + @Pointcut("execution(public * org.springframework.web.servlet.HandlerExceptionResolver.resolveException(..)) && args(request, response, handler, ex)") + private void anyHandlerExceptionResolver(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) { } // NOSONAR + @Pointcut("(anyRestControllerAnnotated() || anyControllerAnnotated()) && anyPublicMethodReturningWebAsyncTask()") private void anyControllerOrRestControllerWithPublicWebAsyncTaskMethod() { } // NOSONAR @@ -129,4 +147,21 @@ public class TraceWebAspect { return webAsyncTask; } + @Around("anyHandlerExceptionResolver(request, response, handler, ex)") + public Object markRequestForSpanClosing(ProceedingJoinPoint pjp, + HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Throwable { + Span currentSpan = this.tracer.getCurrentSpan(); + try { + if (!currentSpan.tags().containsKey(Span.SPAN_ERROR_TAG_NAME)) { + this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(ex)); + } + return pjp.proceed(); + } finally { + if (log.isDebugEnabled()) { + log.debug("Marking span " + currentSpan + " for closure by Trace Filter"); + } + request.setAttribute(TraceFilter.TRACE_CLOSE_SPAN_REQUEST_ATTR, true); + } + } + } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java index 7b761239c..61820cb3f 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceWebAutoConfiguration.java @@ -75,8 +75,8 @@ public class TraceWebAutoConfiguration { } @Bean - public TraceWebAspect traceWebAspect(Tracer tracer, SpanNamer spanNamer) { - return new TraceWebAspect(tracer, spanNamer); + public TraceWebAspect traceWebAspect(Tracer tracer, SpanNamer spanNamer, SpanReporter spanReporter) { + return new TraceWebAspect(tracer, spanNamer, spanReporter); } @Bean diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exceptionresolver/Issue585Tests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exceptionresolver/Issue585Tests.java new file mode 100644 index 000000000..87b457eab --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exceptionresolver/Issue585Tests.java @@ -0,0 +1,171 @@ +package org.springframework.cloud.sleuth.instrument.web.client.exceptionresolver; + +import com.fasterxml.jackson.annotation.JsonInclude; + +import java.time.Instant; +import javax.servlet.http.HttpServletRequest; + +import org.junit.Test; +import org.junit.runner.RunWith; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.autoconfigure.SpringBootApplication; +import org.springframework.boot.context.embedded.LocalServerPort; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.boot.test.web.client.TestRestTemplate; +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.assertions.SleuthAssertions; +import org.springframework.cloud.sleuth.sampler.AlwaysSampler; +import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator; +import org.springframework.context.annotation.Bean; +import org.springframework.http.HttpStatus; +import org.springframework.http.ResponseEntity; +import org.springframework.test.context.junit4.SpringRunner; +import org.springframework.web.bind.annotation.ControllerAdvice; +import org.springframework.web.bind.annotation.ExceptionHandler; +import org.springframework.web.bind.annotation.RequestMapping; +import org.springframework.web.bind.annotation.RequestMethod; +import org.springframework.web.bind.annotation.RequestParam; +import org.springframework.web.bind.annotation.RestController; +import org.springframework.web.servlet.mvc.method.annotation.ResponseEntityExceptionHandler; + +import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then; + +@RunWith(SpringRunner.class) +@SpringBootTest(classes = TestConfig.class, webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT) +public class Issue585Tests { + + TestRestTemplate testRestTemplate = new TestRestTemplate(); + @Autowired ArrayListSpanAccumulator accumulator; + @LocalServerPort int port; + + @Test + public void should_report_span_when_using_custom_exception_resolver() { + ResponseEntity entity = this.testRestTemplate.getForEntity( + "http://localhost:" + this.port + "/sleuthtest?greeting=foo", + String.class); + + then(entity.getStatusCode().value()).isEqualTo(500); + then(new ListOfSpans(this.accumulator.getSpans())) + .hasASpanWithTagEqualTo("custom", "tag") + .hasASpanWithTagKeyEqualTo("error"); + } +} + +@SpringBootApplication +class TestConfig { + + @Bean SpanReporter testSpanReporter() { + return new ArrayListSpanAccumulator(); + } + + @Bean Sampler testSampler() { + return new AlwaysSampler(); + } +} + +@RestController +class TestController { + + private final static Logger logger = LoggerFactory.getLogger(TestController.class); + + @RequestMapping(value = "sleuthtest", method = RequestMethod.GET) + public ResponseEntity testSleuth(@RequestParam String greeting) { + if (greeting.equalsIgnoreCase("hello")) { + return new ResponseEntity<>("Hello World", HttpStatus.OK); + } else { + throw new RuntimeException("This is a test error"); + } + } +} + +@ControllerAdvice +class CustomExceptionHandler extends ResponseEntityExceptionHandler { + + private final static Logger logger = LoggerFactory + .getLogger(CustomExceptionHandler.class); + + @Autowired private Tracer tracer; + + @ExceptionHandler(value = { Exception.class }) + protected ResponseEntity handleDefaultError( + Exception ex, HttpServletRequest request) { + ExceptionResponse exceptionResponse = new ExceptionResponse("ERR-01", + ex.getMessage(), HttpStatus.INTERNAL_SERVER_ERROR, + request.getRequestURI(), Instant.now().toEpochMilli()); + reportErrorSpan(ex.getMessage()); + return new ResponseEntity<>(exceptionResponse, HttpStatus.INTERNAL_SERVER_ERROR); + } + + private void reportErrorSpan(String message) { + Span span = tracer.getCurrentSpan(); + span.logEvent("ERROR: " + message); + tracer.addTag("custom", "tag"); + logger.info("Foo"); + } + +} + +@JsonInclude(JsonInclude.Include.NON_NULL) +class ExceptionResponse { + private String errorCode; + private String errorMessage; + private HttpStatus httpStatus; + private String path; + private Long epochTime; + + ExceptionResponse(String errorCode, String errorMessage, HttpStatus httpStatus, + String path, Long epochTime) { + this.errorCode = errorCode; + this.errorMessage = errorMessage; + this.httpStatus = httpStatus; + this.path = path; + this.epochTime = epochTime; + } + + public String getErrorCode() { + return errorCode; + } + + public void setErrorCode(String errorCode) { + this.errorCode = errorCode; + } + + public String getErrorMessage() { + return errorMessage; + } + + public void setErrorMessage(String errorMessage) { + this.errorMessage = errorMessage; + } + + public HttpStatus getHttpStatus() { + return httpStatus; + } + + public void setHttpStatus(HttpStatus httpStatus) { + this.httpStatus = httpStatus; + } + + public String getPath() { + return path; + } + + public void setPath(String path) { + this.path = path; + } + + public Long getEpochTime() { + return epochTime; + } + + public void setEpochTime(Long epochTime) { + this.epochTime = epochTime; + } + +} \ No newline at end of file