HTTP filter child span renamed

with this change the child span of the HTTP filter span gets changed into a span coming from the Controller aspect. The name of the span becomes the name of the method.
This commit is contained in:
Marcin Grzejszczak
2016-06-22 15:03:28 +02:00
parent 187c58aceb
commit 05e221ef54
9 changed files with 127 additions and 59 deletions

View File

@@ -190,18 +190,9 @@ public class TraceFilter extends GenericFilterBean {
if (spanFromRequest != null) {
addResponseTags(response, exception);
if (spanFromRequest.hasSavedSpan()) {
Span parent = spanFromRequest.getSavedSpan();
if (parent.isRemote()) {
if (log.isDebugEnabled()) {
log.debug("Sending the parent span " + parent + " to Zipkin");
}
parent.logEvent(Span.SERVER_SEND);
parent.stop();
this.spanReporter.report(parent);
}
} else {
spanFromRequest.logEvent(Span.SERVER_SEND);
closeParentSpan(spanFromRequest.getSavedSpan());
}
closeParentSpan(spanFromRequest);
// in case of a response with exception status will close the span when exception dispatch is handled
if (httpStatusSuccessful(response)) {
if (log.isDebugEnabled()) {
@@ -222,6 +213,19 @@ public class TraceFilter extends GenericFilterBean {
}
}
private void closeParentSpan(Span parent) {
if (parent.isRemote()) {
if (log.isDebugEnabled()) {
log.debug("Sending the parent span " + parent + " to Zipkin");
}
parent.stop();
parent.logEvent(Span.SERVER_SEND);
this.spanReporter.report(parent);
} else {
parent.logEvent(Span.SERVER_SEND);
}
}
private boolean httpStatusSuccessful(HttpServletResponse response) {
if (response.getStatus() == 0) {
return false;
@@ -266,10 +270,8 @@ public class TraceFilter extends GenericFilterBean {
log.debug("Found a parent span " + parent + " in the request");
}
addRequestTagsForParentSpan(request, parent);
spanFromRequest = this.tracer.createSpan(name, parent);
if (log.isDebugEnabled()) {
log.debug("Started a new span " + spanFromRequest + " with parent " + parent);
}
spanFromRequest = parent;
this.tracer.continueSpan(spanFromRequest);
if (parent.isRemote()) {
parent.logEvent(Span.SERVER_RECV);
}
@@ -277,8 +279,7 @@ public class TraceFilter extends GenericFilterBean {
if (log.isDebugEnabled()) {
log.debug("Parent span is " + parent + "");
}
}
else {
} else {
if (skip) {
spanFromRequest = this.tracer.createSpan(name, NeverSampler.INSTANCE);
}

View File

@@ -24,6 +24,7 @@ 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.Span;
import org.springframework.cloud.sleuth.SpanNamer;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.instrument.async.TraceContinuingCallable;
@@ -83,6 +84,9 @@ public class TraceWebAspect {
@Pointcut("@within(org.springframework.stereotype.Controller)")
private void anyControllerAnnotated() { } // NOSONAR
@Pointcut("execution(public * *(..))")
private void anyPublicMethod() { } // NOSONAR
@Pointcut("execution(public java.util.concurrent.Callable *(..))")
private void anyPublicMethodReturningCallable() { } // NOSONAR
@@ -95,6 +99,33 @@ public class TraceWebAspect {
@Pointcut("(anyRestControllerAnnotated() || anyControllerAnnotated()) && anyPublicMethodReturningWebAsyncTask()")
private void anyControllerOrRestControllerWithPublicWebAsyncTaskMethod() { } // NOSONAR
@Around("(anyRestControllerAnnotated() || anyControllerAnnotated()) && anyPublicMethod()")
@SuppressWarnings("unchecked")
public Object wrapControllerMethodWithCorrelationId(ProceedingJoinPoint pjp) throws Throwable {
String spanName = toLowerHyphen(pjp.getSignature().getName());
Span span = this.tracer.createSpan(spanName);
log.debug("Wrapping controller method [" + spanName + "] in a span " + span);
try {
//Thread.sleep(0, 1);
return pjp.proceed();
} finally {
this.tracer.close(span);
}
}
static String toLowerHyphen(String name) {
StringBuilder result = new StringBuilder();
for (int i = 0; i < name.length(); i++) {
char c = name.charAt(i);
if (c >= 'A' && c <= 'Z') {
result.append('-').append((char) (c + 'a' - 'A'));
} else {
result.append(c);
}
}
return result.toString();
}
@Around("anyControllerOrRestControllerWithPublicAsyncMethod()")
@SuppressWarnings("unchecked")
public Object wrapWithCorrelationId(ProceedingJoinPoint pjp) throws Throwable {

View File

@@ -24,6 +24,7 @@ import java.util.HashMap;
import java.util.Map;
import java.util.Random;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
@@ -35,8 +36,9 @@ import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.SpanExtractor;
import org.springframework.cloud.sleuth.SpanInjector;
import org.springframework.cloud.sleuth.SpanReporter;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.trace.TestSpanContextHolder;
import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
import org.springframework.context.ApplicationListener;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@@ -51,6 +53,7 @@ import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.RestTemplate;
import static com.jayway.awaitility.Awaitility.await;
import static org.assertj.core.api.BDDAssertions.then;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
@@ -63,6 +66,12 @@ public class TraceFilterCustomExtractorTests {
@Autowired RestTemplate restTemplate;
@Autowired Config config;
@Autowired CustomRestController customRestController;
@Autowired ArrayListSpanAccumulator accumulator;
@Before
public void setup() {
this.accumulator.getSpans().clear();
}
@Test
@SuppressWarnings("unchecked")
@@ -78,7 +87,9 @@ public class TraceFilterCustomExtractorTests {
ResponseEntity<Map> requestHeaders = this.restTemplate.exchange(requestEntity,
Map.class);
then(this.customRestController.span).hasTraceIdEqualTo(traceId);
await().until(() -> then(this.accumulator.getSpans().stream().filter(
span -> span.getSpanId() == spanId).findFirst().get())
.hasTraceIdEqualTo(traceId));
then(requestHeaders.getBody())
.containsEntry("correlationid", Span.idToHex(traceId))
.containsEntry("myspanid", Span.idToHex(spanId))
@@ -128,6 +139,11 @@ public class TraceFilterCustomExtractorTests {
Sampler alwaysSampler() {
return new AlwaysSampler();
}
@Bean
SpanReporter spanReporter() {
return new ArrayListSpanAccumulator();
}
}
// tag::extractor[]
@@ -161,11 +177,9 @@ public class TraceFilterCustomExtractorTests {
@RestController
static class CustomRestController {
Span span;
@RequestMapping("/headers")
public Map<String, String> headers(@RequestHeader HttpHeaders headers) {
this.span = TestSpanContextHolder.getCurrentSpan();
Map<String, String> map = new HashMap<>();
for (String key : headers.keySet()) {
map.put(key, headers.getFirst(key));

View File

@@ -61,7 +61,10 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
MvcResult mvcResult = whenSentPingWithoutTracingData();
then(tracingHeaderFrom(mvcResult)).isNotNull();
then(TraceFilterIntegrationTests.span).hasLoggedAnEvent(Span.SERVER_RECV)
Span parentSpan = this.spanAccumulator.getSpans().stream().filter(
span -> span.getSpanId() == TraceFilterIntegrationTests.span.getParents().get(0))
.findFirst().get();
then(parentSpan).hasLoggedAnEvent(Span.SERVER_RECV)
.hasLoggedAnEvent(Span.SERVER_SEND);
}

View File

@@ -48,10 +48,10 @@ 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.then;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.entry;
import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.get;
@@ -60,6 +60,9 @@ import static org.springframework.test.web.servlet.request.MockMvcRequestBuilder
*/
public class TraceFilterTests {
public static final long PARENT_ID = 10L;
public static final String PARENT_ID_AS_STRING = String.valueOf(PARENT_ID);
@Mock SpanLogger spanLogger;
ArrayListSpanAccumulator spanReporter = new ArrayListSpanAccumulator();
SpanExtractor<HttpServletRequest> spanExtractor = new HttpServletRequestExtractor(Pattern
@@ -146,7 +149,7 @@ public class TraceFilterTests {
@Test
public void startsNewTraceWithParentIdInHeaders() throws Exception {
this.request = builder()
.header(Span.SPAN_ID_NAME, Span.idToHex(1L))
.header(Span.SPAN_ID_NAME, Span.idToHex(PARENT_ID))
.header(Span.TRACE_ID_NAME, Span.idToHex(2L))
.header(Span.PARENT_ID_NAME, Span.idToHex(3L))
.buildRequest(new MockServletContext());
@@ -156,7 +159,7 @@ public class TraceFilterTests {
filter.doFilter(this.request, this.response, this.filterChain);
// this creates a child span which is why we'd expect the parents to include 1L)
assertThat(this.span.getParents()).containsOnly(1L);
assertThat(this.span.getParents()).containsOnly(3L);
assertThat(parentSpan())
.hasATag("http.url", "http://localhost/?foo=bar")
.hasATag("http.host", "localhost")
@@ -167,7 +170,9 @@ public class TraceFilterTests {
private Span parentSpan() {
Optional<Span> parent = this.spanReporter.getSpans().stream()
.filter(span -> span.getName().contains("parent")).findFirst();
.filter(span -> Span.idToHex(span.getSpanId()).equals(PARENT_ID_AS_STRING)
|| span.getName().equals("http:/parent/"))
.findFirst();
assertThat(parent.isPresent()).isTrue();
return parent.get();
}
@@ -221,7 +226,7 @@ public class TraceFilterTests {
@Test
public void continuesSpanFromHeaders() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, this.spanReporter,
@@ -235,7 +240,7 @@ public class TraceFilterTests {
@Test
public void addsAdditionalHeaders() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
this.traceKeys.getHttp().getHeaders().add("x-foo");
@@ -244,13 +249,14 @@ public class TraceFilterTests {
this.request.addHeader("X-Foo", "bar");
filter.doFilter(this.request, this.response, this.filterChain);
assertThat(parentSpan().tags()).contains(entry("http.x-foo", "bar"));
assertThat(parentSpan().tags()).contains(entry("http.x-foo", "bar"));
then(TestSpanContextHolder.getCurrentSpan()).isNull();
}
@Test
public void ensuresThatParentSpanIsStoppedWhenReported() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, spanIsStoppedVeryfingReporter(),
this.spanExtractor, this.spanInjector, this.httpTraceKeysInjector);
@@ -264,7 +270,7 @@ public class TraceFilterTests {
@Test
public void additionalMultiValuedHeader() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext());
this.traceKeys.getHttp().getHeaders().add("x-foo");
@@ -281,7 +287,7 @@ public class TraceFilterTests {
@Test
public void catchesException() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.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);
@@ -306,7 +312,7 @@ public class TraceFilterTests {
@Test
public void detachesSpanWhenResponseStatusIsNot2xx() throws Exception {
this.request = builder().header(Span.SPAN_ID_NAME, 10L)
this.request = builder().header(Span.SPAN_ID_NAME, PARENT_ID)
.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);

View File

@@ -42,13 +42,13 @@ import org.springframework.cloud.netflix.ribbon.RibbonClient;
import org.springframework.cloud.sleuth.Sampler;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.assertions.SleuthAssertions;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.trace.TestSpanContextHolder;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.http.ResponseEntity;
import org.springframework.http.client.SimpleClientHttpRequestFactory;
import org.springframework.test.context.junit4.rules.SpringClassRule;
import org.springframework.test.context.junit4.rules.SpringMethodRule;
import org.springframework.web.bind.annotation.RequestMapping;
@@ -59,9 +59,7 @@ import junitparams.JUnitParamsRunner;
import junitparams.Parameters;
import static junitparams.JUnitParamsRunner.$;
import static org.hamcrest.CoreMatchers.is;
import static org.hamcrest.CoreMatchers.nullValue;
import static org.junit.Assert.assertThat;
import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
@RunWith(JUnitParamsRunner.class)
@SpringApplicationConfiguration(classes = {
@@ -106,9 +104,8 @@ public class WebClientExceptionTests {
// SleuthAssertions.then(e).hasRootCauseInstanceOf(IOException.class);
}
assertThat(ExceptionUtils.getLastException(), is(nullValue()));
SleuthAssertions.then(this.tracer.getCurrentSpan()).isEqualTo(span);
then(ExceptionUtils.getLastException()).isNull();
then(this.tracer.getCurrentSpan()).isEqualTo(span);
this.tracer.close(span);
}
@@ -135,7 +132,10 @@ public class WebClientExceptionTests {
@LoadBalanced
@Bean
public RestTemplate restTemplate() {
return new RestTemplate();
SimpleClientHttpRequestFactory clientHttpRequestFactory = new SimpleClientHttpRequestFactory();
clientHttpRequestFactory.setReadTimeout(1);
clientHttpRequestFactory.setConnectTimeout(1);
return new RestTemplate(clientHttpRequestFactory);
}
@Bean

View File

@@ -17,6 +17,7 @@
package org.springframework.cloud.sleuth.instrument.web.client;
import javax.servlet.http.HttpServletRequest;
import java.lang.invoke.MethodHandles;
import java.util.Collections;
import java.util.HashMap;
import java.util.List;
@@ -29,6 +30,7 @@ import com.netflix.loadbalancer.BaseLoadBalancer;
import com.netflix.loadbalancer.ILoadBalancer;
import com.netflix.loadbalancer.Server;
import org.apache.commons.logging.LogFactory;
import org.junit.After;
import org.junit.ClassRule;
import org.junit.Rule;
@@ -82,6 +84,8 @@ import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
@DirtiesContext
public class WebClientTests {
private static final org.apache.commons.logging.Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
@ClassRule public static final SpringClassRule SCR = new SpringClassRule();
@Rule public final SpringMethodRule springMethodRule = new SpringMethodRule();
@@ -220,6 +224,7 @@ public class WebClientTests {
.forEach(span -> {
int initialSize = span.logs().size();
int distinctSize = span.logs().stream().map(Log::getEvent).distinct().collect(Collectors.toList()).size();
log.info("logs " + span.logs());
then(initialSize).as("there are no duplicate log entries").isEqualTo(distinctSize);
});
then(this.testErrorController.getSpan()).isNotNull();

View File

@@ -103,7 +103,8 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
}
private void thenAllSpansHaveTraceIdEqualTo(long traceId) {
then(this.integrationTestSpanCollector.hashedSpans.stream().allMatch(span -> span.traceId == traceId)).isTrue();
then(this.integrationTestSpanCollector.hashedSpans.stream()
.allMatch(span -> span.traceId == traceId)).describedAs("All spans have same trace id").isTrue();
}
private void thenTheSpansHaveProperParentStructure() {
@@ -112,20 +113,17 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
Optional<Span> eventSentSpan = findSpanWithAnnotation(Constants.SERVER_SEND);
Optional<Span> eventReceivedSpan = findSpanWithAnnotation(Constants.CLIENT_RECV);
Optional<Span> lastHttpSpansParent = findLastHttpSpansParent();
thenAllSpansArePresent(firstHttpSpan, eventSpans, lastHttpSpansParent, eventSentSpan, eventReceivedSpan);
// "http:/parent/" -> "http:/" -> "message:messages" -> "http:/foo" (CS + CR) -> "http:/foo" (SS) -> "http:/foo"
// "http:/parent/" -> "home" -> "message:messages" -> "http:/foo" (CS + CR) -> "http:/foo" (SS) -> "foo"
Collections.sort(this.integrationTestSpanCollector.hashedSpans, (s1, s2) -> s1.timestamp.compareTo(s2.timestamp));
then(this.integrationTestSpanCollector.hashedSpans).hasSize(6);
for (int i=0; i<this.integrationTestSpanCollector.hashedSpans.size(); i++) {
if (i - 1 >= 0) {
Span parent = this.integrationTestSpanCollector.hashedSpans.get(i - 1);
Span current = this.integrationTestSpanCollector.hashedSpans.get(i);
// there is a pair of spans having cs/cr and ss/sr
if (current.id != parent.id) {
then(current.parentId).isEqualTo(parent.id);
}
}
}
thenAllSpansArePresent(firstHttpSpan, eventSpans, lastHttpSpansParent, eventSentSpan, eventReceivedSpan);
then(this.integrationTestSpanCollector.hashedSpans).as("There were 6 spans").hasSize(6);
log.info("Checking the parent child structure");
List<Optional<Span>> parentChild = this.integrationTestSpanCollector.hashedSpans.stream()
.filter(span -> span.parentId != null)
.map(span -> this.integrationTestSpanCollector.hashedSpans.stream().filter(span1 -> span1.id == span.parentId).findAny()
).collect(Collectors.toList());
log.info("List of parents and children " + parentChild);
then(parentChild.stream().allMatch(Optional::isPresent)).isTrue();
}
private Optional<Span> findLastHttpSpansParent() {
@@ -148,12 +146,21 @@ public class MessagingApplicationTests extends AbstractIntegrationTest {
private Optional<Span> findFirstHttpRequestSpan() {
return this.integrationTestSpanCollector.hashedSpans.stream()
.filter(span -> "http:/".equals(span.name) && span.parentId != null).findFirst();
// home is the name of the method
.filter(span -> "home".equals(span.name)).findFirst();
}
private void thenAllSpansArePresent(Optional<Span> firstHttpSpan,
List<Span> eventSpans, Optional<Span> lastHttpSpan,
Optional<Span> eventSentSpan, Optional<Span> eventReceivedSpan) {
log.info("Found following spans");
log.info("First http span " + firstHttpSpan);
log.info("Event spans " + eventSpans);
log.info("Event sent span " + eventSentSpan);
log.info("Event received span " + eventReceivedSpan);
log.info("Last http span " + lastHttpSpan);
log.info("All found spans \n" + this.integrationTestSpanCollector.hashedSpans
.stream().map(Span::toString).collect(Collectors.joining("\n")));
then(firstHttpSpan.isPresent()).isTrue();
then(eventSpans).isNotEmpty();
then(eventSentSpan.isPresent()).isTrue();

View File

@@ -15,6 +15,7 @@
*/
package tools;
import java.lang.invoke.MethodHandles;
import java.net.URI;
import java.util.ArrayList;
import java.util.Collection;
@@ -23,6 +24,9 @@ import java.util.List;
import java.util.Optional;
import java.util.stream.Collectors;
import com.jayway.awaitility.Awaitility;
import com.jayway.awaitility.core.ConditionFactory;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.junit.After;
@@ -35,9 +39,6 @@ import org.springframework.http.RequestEntity;
import org.springframework.http.ResponseEntity;
import org.springframework.web.client.RestTemplate;
import com.jayway.awaitility.Awaitility;
import com.jayway.awaitility.core.ConditionFactory;
import zipkin.Codec;
import zipkin.Span;
@@ -49,7 +50,7 @@ import static org.assertj.core.api.BDDAssertions.then;
*/
public abstract class AbstractIntegrationTest {
private static final Log log = LogFactory.getLog(AbstractIntegrationTest.class);
protected static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
protected static final int POLL_INTERVAL = 1;
protected static final int TIMEOUT = 20;