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

Spans are continued in Handler Interceptors (#474)

Browse Source 
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
This commit is contained in:
Marcin Grzejszczak
2016-12-16 13:02:58 +01:00
committed by GitHub
parent 0f4427bbf3
commit ee8c73df53
11 changed files with 153 additions and 49 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -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");
}

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

@@ -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);

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

@@ -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.

1
spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/trace/DefaultTracer.java
View File

@@ -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;

10
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/assertions/ListOfSpansAssert.java
View File

@@ -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<ListOfSpansAssert, ListOfS
.collect(toList());
if (matchingSpans.isEmpty()) {
failWithMessage("Expected spans \n <%s> \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<ListOfSpansAssert, ListOfS
@Override
protected void failWithMessage(String errorMessage, Object... arguments) {
log.error(errorMessage);
log.error(String.format(errorMessage, arguments));
super.failWithMessage(errorMessage, arguments);
}
}

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

@@ -17,6 +17,7 @@ import org.springframework.boot.test.SpringApplicationConfiguration;
import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.TraceKeys;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.instrument.DefaultTestAutoConfiguration;
import org.springframework.cloud.sleuth.instrument.web.common.AbstractMvcIntegrationTest;
@@ -61,10 +62,11 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
public void should_create_and_return_trace_in_HTTP_header() throws Exception {
whenSentPingWithoutTracingData();
Span parentSpan = this.spanAccumulator.getSpans().stream().filter(
span -> 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();
}

3
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/servererrors/FeignClientServerErrorTests.java
View File

@@ -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");
});
}

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

@@ -114,7 +114,8 @@ public class WebClientTests {
then(getHeader(response, Span.SPAN_ID_NAME)).isNull();
then(this.listener.getSpans()).isNotEmpty();
Optional<Span> 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")

29
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469.java Normal file
View File

@@ -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");
}
}

68
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/view/Issue469Tests.java Normal file
View File

@@ -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);
}
}

7
spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-messaging/src/test/java/integration/MessagingApplicationTests.java
View File

@@ -113,10 +113,10 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
Optional<Span> eventSentSpan = findSpanWithAnnotation(Constants.SERVER_SEND);
Optional<Span> eventReceivedSpan = findSpanWithAnnotation(Constants.CLIENT_RECV);
Optional<Span> 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<Optional<Span>> parentChild = this.integrationTestSpanCollector.hashedSpans.stream()
.filter(span -> span.parentId != null)
@@ -147,7 +147,8 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
private Optional<Span> 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<Span> firstHttpSpan,