From ee8c73df53478b031e7cd080b328a7b2131b391f Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Fri, 16 Dec 2016 13:02:58 +0100 Subject: [PATCH] Spans are continued in Handler Interceptors (#474) without this change an explicit new span is created on the server side. Its name is equal to the method name of the controller. It introduces some nice advantages in terms of readability of trace. with this change we're continuing a previous span on the server side. We're attaching the tags and logs to that span with information about controller class and controller name. Also events related to start and finish of the controller are there. fixes #471 #469 #427 --- .../sleuth/instrument/web/TraceFilter.java | 2 +- .../web/TraceHandlerInterceptor.java | 63 +++++++++-------- .../web/TraceRequestAttributes.java | 6 ++ .../cloud/sleuth/trace/DefaultTracer.java | 1 + .../sleuth/assertions/ListOfSpansAssert.java | 10 +-- .../web/TraceFilterIntegrationTests.java | 10 +-- .../FeignClientServerErrorTests.java | 3 - .../client/integration/WebClientTests.java | 3 +- .../sleuth/instrument/web/view/Issue469.java | 29 ++++++++ .../instrument/web/view/Issue469Tests.java | 68 +++++++++++++++++++ .../MessagingApplicationTests.java | 7 +- 11 files changed, 153 insertions(+), 49 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469.java create mode 100644 spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469Tests.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 e9e04ac9f..3dfb72be4 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 @@ -221,7 +221,7 @@ public class TraceFilter extends GenericFilterBean { log.debug( "Won't detach the span " + span + " since error has already been handled"); } - } else { + } else if (this.tracer.isTracing()) { if (log.isDebugEnabled()) { log.debug("Detaching the span " + span + " since the response was unsuccessful"); } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHandlerInterceptor.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHandlerInterceptor.java index 538195de3..ff5a144f8 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHandlerInterceptor.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHandlerInterceptor.java @@ -62,26 +62,18 @@ public class TraceHandlerInterceptor extends HandlerInterceptorAdapter { @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { - if (isErrorControllerRelated(request)) { - if (log.isDebugEnabled()) { - log.debug("Skipping creation of a span for error controller processing"); - } - return true; - } - if (isSpanContinued(request)) { - if (log.isDebugEnabled()) { - log.debug("Skipping creation of a span since the span is continued"); - } - return true; - } String spanName = spanName(handler); - Span span = getTracer().createSpan(spanName); + boolean continueSpan = getRootSpanFromAttribute(request) != null; + Span span = continueSpan ? getRootSpanFromAttribute(request) : getTracer().createSpan(spanName); if (log.isDebugEnabled()) { log.debug("Created new span " + span + " with name [" + spanName + "]"); } addClassMethodTag(handler, span); addClassNameTag(handler, span); setSpanInAttribute(request, span); + if (!continueSpan) { + setNewSpanCreatedAttribute(request, span); + } return true; } @@ -123,7 +115,7 @@ public class TraceHandlerInterceptor extends HandlerInterceptorAdapter { @Override public void afterConcurrentHandlingStarted(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { - Span spanFromRequest = getSpanFromAttribute(request); + Span spanFromRequest = getNewSpanFromAttribute(request); Span rootSpanFromRequest = getRootSpanFromAttribute(request); if (log.isDebugEnabled()) { log.debug("Closing the span " + spanFromRequest + " and detaching its parent " + rootSpanFromRequest + " since the request is asynchronous"); @@ -141,28 +133,27 @@ public class TraceHandlerInterceptor extends HandlerInterceptorAdapter { } return; } - if (isSpanContinued(request)) { - if (log.isDebugEnabled()) { - log.debug("Skipping closing of a span since it's been continued"); - } - return; - } - Span span = getSpanFromAttribute(request); - if (log.isDebugEnabled()) { - log.debug("Closing span " + span); - } + Span span = getRootSpanFromAttribute(request); if (ex != null) { - getTracer().addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(ex)); + String errorMsg = ExceptionUtils.getExceptionMessage(ex); + if (log.isDebugEnabled()) { + log.debug("Adding an error tag [" + errorMsg + "] to span " + span + ""); + } + getTracer().addTag(Span.SPAN_ERROR_TAG_NAME, errorMsg); + } + if (getNewSpanFromAttribute(request) != null) { + if (log.isDebugEnabled()) { + log.debug("Closing span " + span); + } + Span newSpan = getNewSpanFromAttribute(request); + getTracer().continueSpan(newSpan); + getTracer().close(newSpan); + clearNewSpanCreatedAttribute(request); } - getTracer().close(span); } - private boolean isSpanContinued(HttpServletRequest request) { - return request.getAttribute(TraceRequestAttributes.SPAN_CONTINUED_REQUEST_ATTR) != null; - } - - private Span getSpanFromAttribute(HttpServletRequest request) { - return (Span) request.getAttribute(TraceRequestAttributes.HANDLED_SPAN_REQUEST_ATTR); + private Span getNewSpanFromAttribute(HttpServletRequest request) { + return (Span) request.getAttribute(TraceRequestAttributes.NEW_SPAN_REQUEST_ATTR); } private Span getRootSpanFromAttribute(HttpServletRequest request) { @@ -173,6 +164,14 @@ public class TraceHandlerInterceptor extends HandlerInterceptorAdapter { request.setAttribute(TraceRequestAttributes.HANDLED_SPAN_REQUEST_ATTR, span); } + private void setNewSpanCreatedAttribute(HttpServletRequest request, Span span) { + request.setAttribute(TraceRequestAttributes.NEW_SPAN_REQUEST_ATTR, span); + } + + private void clearNewSpanCreatedAttribute(HttpServletRequest request) { + request.removeAttribute(TraceRequestAttributes.NEW_SPAN_REQUEST_ATTR); + } + private Tracer getTracer() { if (this.tracer == null) { this.tracer = this.beanFactory.getBean(Tracer.class); diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceRequestAttributes.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceRequestAttributes.java index 683293807..1b3ccfbb0 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceRequestAttributes.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceRequestAttributes.java @@ -31,6 +31,12 @@ public final class TraceRequestAttributes { public static final String HANDLED_SPAN_REQUEST_ATTR = TraceRequestAttributes.class.getName() + ".TRACE_HANDLED"; + /** + * Set if Handler interceptor has executed some logic + */ + public static final String NEW_SPAN_REQUEST_ATTR = TraceRequestAttributes.class.getName() + + ".TRACE_HANDLED_NEW_SPAN"; + /** * Attribute set when the {@link org.springframework.cloud.sleuth.Span} got continued in the {@link TraceFilter}. * The Sleuth tracing components will most likely continue the current Span instead of creating a new one. diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java index a1cb5edd0..f9dc325b8 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java @@ -18,6 +18,7 @@ package org.springframework.cloud.sleuth.trace; import java.util.Random; import java.util.concurrent.Callable; + import org.springframework.cloud.sleuth.Sampler; import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.SpanNamer; diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java index 06fb23942..b1e237d75 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java @@ -16,6 +16,9 @@ package org.springframework.cloud.sleuth.assertions; +import com.fasterxml.jackson.core.JsonProcessingException; +import com.fasterxml.jackson.databind.ObjectMapper; + import java.util.ArrayList; import java.util.HashMap; import java.util.List; @@ -26,9 +29,6 @@ import org.apache.commons.logging.LogFactory; import org.assertj.core.api.AbstractAssert; import org.springframework.cloud.sleuth.Span; -import com.fasterxml.jackson.core.JsonProcessingException; -import com.fasterxml.jackson.databind.ObjectMapper; - import static java.util.stream.Collectors.joining; import static java.util.stream.Collectors.toList; import static org.assertj.core.api.Assertions.assertThat; @@ -106,7 +106,7 @@ public class ListOfSpansAssert extends AbstractAssert \nto contain at least one span with tag key " - + "equal to <%s> and value equal to <%s>", spansToString(), tagKey, tagValue); + + "equal to <%s> and value equal to <%s>.\n\n", spansToString(), tagKey, tagValue); } return this; } @@ -152,7 +152,7 @@ public class ListOfSpansAssert extends AbstractAssert span.getSpanId() == TraceFilterIntegrationTests.span.getParents().get(0)) - .findFirst().get(); - then(parentSpan).hasLoggedAnEvent(Span.SERVER_RECV) + then(this.spanAccumulator.getSpans()).hasSize(1); + Span span = this.spanAccumulator.getSpans().get(0); + then(span).hasLoggedAnEvent(Span.SERVER_RECV) + .hasATagWithKey(new TraceKeys().getMvc().getControllerClass()) + .hasATagWithKey(new TraceKeys().getMvc().getControllerMethod()) .hasLoggedAnEvent(Span.SERVER_SEND); then(ExceptionUtils.getLastException()).isNull(); } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/servererrors/FeignClientServerErrorTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/servererrors/FeignClientServerErrorTests.java index 5cd501607..d102beca5 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/servererrors/FeignClientServerErrorTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/servererrors/FeignClientServerErrorTests.java @@ -101,9 +101,6 @@ public class FeignClientServerErrorTests { 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"); }); } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/integration/WebClientTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/integration/WebClientTests.java index 14c7c8ba5..336401d13 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/integration/WebClientTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/integration/WebClientTests.java @@ -114,7 +114,8 @@ public class WebClientTests { then(getHeader(response, Span.SPAN_ID_NAME)).isNull(); then(this.listener.getSpans()).isNotEmpty(); Optional noTraceSpan = new ArrayList<>(this.listener.getSpans()).stream().filter(span -> - "http:/notrace".equals(span.getName()) && !span.tags().isEmpty()).findFirst(); + "http:/notrace".equals(span.getName()) && !span.tags().isEmpty() + && span.tags().containsKey("http.path")).findFirst(); then(noTraceSpan.isPresent()).isTrue(); // TODO: matches cause there is an issue with Feign not providing the full URL at the interceptor level then(noTraceSpan.get()).matchesATag("http.url", ".*/notrace") diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469.java new file mode 100644 index 000000000..e73f7fdad --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469.java @@ -0,0 +1,29 @@ +/* + * Copyright 2013-2016 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.cloud.sleuth.instrument.web.view; + +import org.springframework.boot.autoconfigure.EnableAutoConfiguration; +import org.springframework.web.servlet.config.annotation.ViewControllerRegistry; +import org.springframework.web.servlet.config.annotation.WebMvcConfigurerAdapter; + +@EnableAutoConfiguration +public class Issue469 extends WebMvcConfigurerAdapter { + + @Override public void addViewControllers(ViewControllerRegistry registry) { + registry.addViewController("/welcome").setViewName("welcome"); + } +} \ No newline at end of file diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469Tests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469Tests.java new file mode 100644 index 000000000..1cfbd65d5 --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469Tests.java @@ -0,0 +1,68 @@ +/* + * Copyright 2013-2016 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.cloud.sleuth.instrument.web.view; + +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.test.SpringApplicationConfiguration; +import org.springframework.boot.test.WebIntegrationTest; +import org.springframework.cloud.sleuth.Tracer; +import org.springframework.cloud.sleuth.util.ExceptionUtils; +import org.springframework.core.env.Environment; +import org.springframework.test.context.TestPropertySource; +import org.springframework.test.context.junit4.SpringJUnit4ClassRunner; +import org.springframework.web.client.RestTemplate; + +import static org.assertj.core.api.BDDAssertions.then; + +@RunWith(SpringJUnit4ClassRunner.class) +@SpringApplicationConfiguration(classes = Issue469.class) +@TestPropertySource(properties = {"spring.mvc.view.prefix=/WEB-INF/jsp/", + "spring.mvc.view.suffix=.jsp"}) +@WebIntegrationTest({ "server.port=0" }) +public class Issue469Tests { + + @Autowired Tracer tracer; + @Autowired Environment environment; + RestTemplate restTemplate = new RestTemplate(); + + @Before + public void setup() { + ExceptionUtils.setFail(true); + } + + @Test + public void should_not_result_in_tracing_exceptions_when_using_view_controllers() throws Exception { + try { + this.restTemplate + .getForObject("http://localhost:" + port() + "/welcome", String.class); + } catch (Exception e) { + // JSPs are not rendered + then(e).hasMessage("404 Not Found"); + } + + then(ExceptionUtils.getLastException()).isNull(); + then(this.tracer.getCurrentSpan()).isNull(); + } + + private int port() { + return this.environment.getProperty("local.server.port", Integer.class); + } + +} \ No newline at end of file diff --git a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java index b8ccb3123..7060429d0 100644 --- a/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java +++ b/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java @@ -113,10 +113,10 @@ public class MessagingApplicationTests extends AbstractIntegrationTest { Optional eventSentSpan = findSpanWithAnnotation(Constants.SERVER_SEND); Optional eventReceivedSpan = findSpanWithAnnotation(Constants.CLIENT_RECV); Optional lastHttpSpansParent = findLastHttpSpansParent(); - // "http:/parent/" -> "home" -> "message:messages" -> "http:/foo" (CS + CR) -> "http:/foo" (SS) -> "foo" + // "http:/parent/" -> "message:messages" -> "http:/foo" (CS + CR) -> "http:/foo" (SS) Collections.sort(this.integrationTestSpanCollector.hashedSpans); thenAllSpansArePresent(firstHttpSpan, eventSpans, lastHttpSpansParent, eventSentSpan, eventReceivedSpan); - then(this.integrationTestSpanCollector.hashedSpans).as("There were 6 spans").hasSize(6); + then(this.integrationTestSpanCollector.hashedSpans).as("There were 4 spans").hasSize(4); log.info("Checking the parent child structure"); List> parentChild = this.integrationTestSpanCollector.hashedSpans.stream() .filter(span -> span.parentId != null) @@ -147,7 +147,8 @@ public class MessagingApplicationTests extends AbstractIntegrationTest { private Optional findFirstHttpRequestSpan() { return this.integrationTestSpanCollector.hashedSpans.stream() // home is the name of the method - .filter(span -> "home".equals(span.name)).findFirst(); + .filter(span -> span.binaryAnnotations.stream() + .anyMatch(binaryAnnotation -> new String(binaryAnnotation.value).equals("home"))).findFirst(); } private void thenAllSpansArePresent(Optional firstHttpSpan,