Fix trace filter so async requests are handled properly

Previously, if a trace id came into the filter from the caller and
the controller was async, the span context was not properly managed
resulting in warnings in logs.

Fixes gh-137
This commit is contained in:
Dave Syer
2016-01-30 11:56:40 +00:00
parent cd37335153
commit 4f3c731d37
6 changed files with 199 additions and 113 deletions

View File

@@ -27,10 +27,8 @@ import java.util.Map;
import org.springframework.util.Assert;
import lombok.Builder;
import lombok.EqualsAndHashCode;
import lombok.Getter;
import lombok.Singular;
import lombok.ToString;
/**
* Class for gathering and reporting statistics about a block of execution.
@@ -43,13 +41,11 @@ import lombok.ToString;
* @author Marcin Grzejszczak
*/
/*
OpenTracing spans can affect the trace tree by creating children. In this way,
they are like scoped tracers. Sleuth spans are DTOs, whose sole responsibility
is the current span in the trace tree.
*/
* OpenTracing spans can affect the trace tree by creating children. In this way, they are
* like scoped tracers. Sleuth spans are DTOs, whose sole responsibility is the current
* span in the trace tree.
*/
@Builder(toBuilder = true)
@ToString
@EqualsAndHashCode
@Getter
public class Span {
@@ -59,9 +55,8 @@ public class Span {
public static final String TRACE_ID_NAME = "X-Trace-Id";
public static final String SPAN_NAME_NAME = "X-Span-Name";
public static final String SPAN_ID_NAME = "X-Span-Id";
public static final List<String> HEADERS = Arrays
.asList(SPAN_ID_NAME, TRACE_ID_NAME, SPAN_NAME_NAME, PARENT_ID_NAME,
PROCESS_ID_NAME, NOT_SAMPLED_NAME);
public static final List<String> HEADERS = Arrays.asList(SPAN_ID_NAME, TRACE_ID_NAME,
SPAN_NAME_NAME, PARENT_ID_NAME, PROCESS_ID_NAME, NOT_SAMPLED_NAME);
public static final String SPAN_EXPORT_NAME = "X-Span-Export";
private final long begin;
@@ -100,13 +95,14 @@ public class Span {
public Span(long begin, long end, String name, long traceId, List<Long> parents,
long spanId, boolean remote, boolean exportable, String processId) {
this(begin, end, name, traceId, parents, spanId, remote, exportable, processId, null);
this(begin, end, name, traceId, parents, spanId, remote, exportable, processId,
null);
}
public Span(long begin, long end, String name, long traceId, List<Long> parents,
long spanId, boolean remote, boolean exportable, String processId,
Span savedSpan) {
this.begin = begin<=0 ? System.currentTimeMillis() : begin;
this.begin = begin <= 0 ? System.currentTimeMillis() : begin;
this.end = end;
this.name = name;
this.traceId = traceId;
@@ -118,7 +114,7 @@ public class Span {
this.savedSpan = savedSpan;
}
//for serialization
// for serialization
private Span() {
this.begin = 0;
this.name = null;
@@ -135,8 +131,8 @@ public class Span {
public synchronized void stop() {
if (this.end == 0) {
if (this.begin == 0) {
throw new IllegalStateException("Span for " + this.name
+ " has not been started");
throw new IllegalStateException(
"Span for " + this.name + " has not been started");
}
this.end = System.currentTimeMillis();
}
@@ -300,4 +296,34 @@ public class Span {
Assert.hasText(hexString, "Can't convert empty hex string to long");
return new BigInteger(hexString, 16).longValue();
}
@Override
public String toString() {
return "[Trace: " + toHex(this.traceId) + ", Span: " + toHex(this.spanId) + "]";
}
@Override
public int hashCode() {
final int prime = 31;
int result = 1;
result = prime * result + (int) (this.spanId ^ (this.spanId >>> 32));
result = prime * result + (int) (this.traceId ^ (this.traceId >>> 32));
return result;
}
@Override
public boolean equals(Object obj) {
if (this == obj)
return true;
if (obj == null)
return false;
if (getClass() != obj.getClass())
return false;
Span other = (Span) obj;
if (this.spanId != other.spanId)
return false;
if (this.traceId != other.traceId)
return false;
return true;
}
}

View File

@@ -15,6 +15,20 @@
*/
package org.springframework.cloud.sleuth.instrument.web;
import static org.springframework.util.StringUtils.hasText;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Collections;
import java.util.Enumeration;
import java.util.Random;
import java.util.regex.Pattern;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Span.SpanBuilder;
import org.springframework.cloud.sleuth.Tracer;
@@ -32,27 +46,15 @@ import org.springframework.util.StringUtils;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.UrlPathHelper;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Collections;
import java.util.Enumeration;
import java.util.Random;
import java.util.regex.Pattern;
import static org.springframework.util.StringUtils.hasText;
/**
* Filter that takes the value of the {@link Span#SPAN_ID_NAME} and
* {@link Span#TRACE_ID_NAME} header from either request or response and uses them to
* create a new span.
*
* <p>In order to keep the size of spans manageable, this only add tags defined in {@link TraceKeys}.
* If you need to add additional tags, such as headers subtype this and override
* {@link #addRequestTags} or {@link #addResponseTags}.
* <p>
* In order to keep the size of spans manageable, this only add tags defined in
* {@link TraceKeys}. If you need to add additional tags, such as headers subtype this and
* override {@link #addRequestTags} or {@link #addResponseTags}.
*
* @see Tracer
* @see TraceKeys
@@ -82,12 +84,12 @@ public class TraceFilter extends OncePerRequestFilter
private UrlPathHelper urlPathHelper = new UrlPathHelper();
private ApplicationEventPublisher publisher;
public TraceFilter(Tracer tracer, TraceKeys traceKeys) {
this(tracer, traceKeys, DEFAULT_SKIP_PATTERN, new Random());
}
public TraceFilter(Tracer tracer, TraceKeys traceKeys, Pattern skipPattern, Random random) {
public TraceFilter(Tracer tracer, TraceKeys traceKeys, Pattern skipPattern,
Random random) {
this.tracer = tracer;
this.traceKeys = traceKeys;
this.skipPattern = skipPattern;
@@ -118,47 +120,54 @@ public class TraceFilter extends OncePerRequestFilter
}
String name = "http" + uri;
if (hasHeader(request, response, Span.TRACE_ID_NAME)) {
long traceId = Span.fromHex(getHeader(request, response, Span.TRACE_ID_NAME));
long spanId = hasHeader(request, response, Span.SPAN_ID_NAME) ?
Span.fromHex(getHeader(request, response, Span.SPAN_ID_NAME)) :
this.random.nextLong();
if (spanFromRequest == null) {
if (hasHeader(request, response, Span.TRACE_ID_NAME)) {
long traceId = Span
.fromHex(getHeader(request, response, Span.TRACE_ID_NAME));
long spanId = hasHeader(request, response, Span.SPAN_ID_NAME)
? Span.fromHex(getHeader(request, response, Span.SPAN_ID_NAME))
: this.random.nextLong();
SpanBuilder span = Span.builder().traceId(traceId).spanId(spanId);
if (skip) {
span.exportable(false);
}
String processId = getHeader(request, response, Span.PROCESS_ID_NAME);
String parentName = getHeader(request, response, Span.SPAN_NAME_NAME);
if (StringUtils.hasText(parentName)) {
span.name(parentName);
} else {
span.name("parent/" + name);
}
if (StringUtils.hasText(processId)) {
span.processId(processId);
}
if (hasHeader(request, response, Span.PARENT_ID_NAME)) {
span.parent(
Span.fromHex(getHeader(request, response, Span.PARENT_ID_NAME)));
}
span.remote(true);
SpanBuilder span = Span.builder().traceId(traceId).spanId(spanId);
if (skip) {
span.exportable(false);
}
String processId = getHeader(request, response, Span.PROCESS_ID_NAME);
String parentName = getHeader(request, response, Span.SPAN_NAME_NAME);
if (StringUtils.hasText(parentName)) {
span.name(parentName);
}
else {
span.name("parent/" + name);
}
if (StringUtils.hasText(processId)) {
span.processId(processId);
}
if (hasHeader(request, response, Span.PARENT_ID_NAME)) {
span.parent(Span
.fromHex(getHeader(request, response, Span.PARENT_ID_NAME)));
}
span.remote(true);
Span parent = span.build();
spanFromRequest = this.tracer.joinTrace(name, parent);
publish(new ServerReceivedEvent(this, parent, spanFromRequest));
request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
Span parent = span.build();
spanFromRequest = this.tracer.joinTrace(name, parent);
publish(new ServerReceivedEvent(this, parent, spanFromRequest));
request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
}
else {
if (skip) {
spanFromRequest = this.tracer.startTrace(name, IsTracingSampler.INSTANCE
);
}
else {
spanFromRequest = this.tracer.startTrace(name);
if (skip) {
spanFromRequest = this.tracer.startTrace(name,
IsTracingSampler.INSTANCE);
}
else {
spanFromRequest = this.tracer.startTrace(name);
}
request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
}
request.setAttribute(TRACE_REQUEST_ATTR, spanFromRequest);
}
else {
this.tracer.continueSpan(spanFromRequest);
}
Throwable exception = null;
@@ -174,6 +183,7 @@ public class TraceFilter extends OncePerRequestFilter
}
finally {
if (isAsyncStarted(request) || request.isAsyncStarted()) {
this.tracer.detach(spanFromRequest);
// TODO: how to deal with response annotations and async?
return;
}
@@ -210,11 +220,9 @@ public class TraceFilter extends OncePerRequestFilter
protected void addRequestTags(HttpServletRequest request) {
String uri = this.urlPathHelper.getPathWithinApplication(request);
this.tracer.addTag(this.traceKeys.getHttp().getUrl(), getFullUrl(request));
this.tracer.addTag(this.traceKeys.getHttp().getHost(),
request.getServerName());
this.tracer.addTag(this.traceKeys.getHttp().getHost(), request.getServerName());
this.tracer.addTag(this.traceKeys.getHttp().getPath(), uri);
this.tracer.addTag(this.traceKeys.getHttp().getMethod(),
request.getMethod());
this.tracer.addTag(this.traceKeys.getHttp().getMethod(), request.getMethod());
for (String name : this.traceKeys.getHttp().getHeaders()) {
Enumeration<String> values = request.getHeaders(name);
if (values.hasMoreElements()) {
@@ -236,7 +244,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 > 299)) {
this.tracer.addTag(this.traceKeys.getHttp().getStatusCode(),
String.valueOf(response.getStatus()));
}
@@ -272,7 +280,8 @@ public class TraceFilter extends OncePerRequestFilter
if (queryString == null) {
return requestURI.toString();
} else {
}
else {
return requestURI.append('?').append(queryString).toString();
}
}

View File

@@ -16,6 +16,11 @@
package org.springframework.cloud.sleuth.trace;
import static org.springframework.cloud.sleuth.util.ExceptionUtils.warn;
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.Tracer;
@@ -27,11 +32,6 @@ import org.springframework.cloud.sleuth.instrument.TraceRunnable;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.context.ApplicationEventPublisher;
import java.util.Random;
import java.util.concurrent.Callable;
import static org.springframework.cloud.sleuth.util.ExceptionUtils.warn;
/**
* @author Spencer Gibb
*/
@@ -43,8 +43,8 @@ public class DefaultTracer implements Tracer {
private final Random random;
public DefaultTracer(Sampler defaultSampler,
Random random, ApplicationEventPublisher publisher) {
public DefaultTracer(Sampler defaultSampler, Random random,
ApplicationEventPublisher publisher) {
this.defaultSampler = defaultSampler;
this.random = random;
this.publisher = publisher;
@@ -57,8 +57,7 @@ public class DefaultTracer implements Tracer {
}
Span currentSpan = getCurrentSpan();
if (currentSpan != null && !parent.equals(currentSpan)) {
warn("Warn during joining trace: thread " + Thread.currentThread().getName()
+ " tried to start a new Span " + "with parent " + parent.toString()
warn("Tried to start a new Span with parent " + parent
+ ", but there is already a " + "currentSpan " + currentSpan);
}
return continueSpan(createChild(parent, name));
@@ -78,8 +77,8 @@ public class DefaultTracer implements Tracer {
else {
// Non-exportable so we keep the trace but not other data
long id = createId();
span = Span.builder().begin(System.currentTimeMillis()).name(name)
.traceId(id).spanId(id).exportable(false).build();
span = Span.builder().begin(System.currentTimeMillis()).name(name).traceId(id)
.spanId(id).exportable(false).build();
this.publisher.publishEvent(new SpanAcquiredEvent(this, span));
}
return continueSpan(span);
@@ -91,11 +90,10 @@ public class DefaultTracer implements Tracer {
return null;
}
Span cur = SpanContextHolder.getCurrentSpan();
if (cur != span) {
if (!span.equals(cur)) {
ExceptionUtils.warn("Tried to detach trace span but "
+ "it is not the current span for the '"
+ Thread.currentThread().getName() + "' thread: " + span
+ ". You have " + "probably forgotten to close or detach " + cur);
+ "it is not the current span: " + span
+ ". You may have forgotten to close or detach " + cur);
}
else {
if (span.hasSavedSpan()) {
@@ -115,11 +113,10 @@ public class DefaultTracer implements Tracer {
}
Span cur = SpanContextHolder.getCurrentSpan();
Span savedSpan = span.getSavedSpan();
if (cur != span) {
ExceptionUtils.warn("Tried to close trace span but "
+ "it is not the current span for the '"
+ Thread.currentThread().getName() + "' thread" + span
+ ". You have " + "probably forgotten to close or detach " + cur);
if (!span.equals(cur)) {
ExceptionUtils.warn(
"Tried to close span but " + "it is not the current span: " + span
+ ". You may have forgotten to close or detach " + cur);
}
else {
span.stop();
@@ -140,8 +137,8 @@ public class DefaultTracer implements Tracer {
protected Span createChild(Span parent, String name) {
long id = createId();
if (parent == null) {
Span span = Span.builder().begin(System.currentTimeMillis())
.name(name).traceId(id).spanId(id).build();
Span span = Span.builder().begin(System.currentTimeMillis()).name(name)
.traceId(id).spanId(id).build();
this.publisher.publishEvent(new SpanAcquiredEvent(this, span));
return span;
}
@@ -150,9 +147,9 @@ public class DefaultTracer implements Tracer {
Span span = createSpan(null, parent);
SpanContextHolder.setCurrentSpan(span);
}
Span span = Span.builder().begin(System.currentTimeMillis())
.name(name).traceId(parent.getTraceId()).parent(parent.getSpanId())
.spanId(id).processId(parent.getProcessId()).build();
Span span = Span.builder().begin(System.currentTimeMillis()).name(name)
.traceId(parent.getTraceId()).parent(parent.getSpanId()).spanId(id)
.processId(parent.getProcessId()).build();
this.publisher.publishEvent(new SpanAcquiredEvent(this, parent, span));
return span;
}
@@ -173,6 +170,9 @@ public class DefaultTracer implements Tracer {
}
protected Span createSpan(Span saved, Span span) {
if (saved == null && span.getSavedSpan() != null) {
saved = span.getSavedSpan();
}
return new Span(span, saved);
}

View File

@@ -23,7 +23,14 @@ import lombok.extern.apachecommons.CommonsLog;
*/
@CommonsLog
public abstract class ExceptionUtils {
private static boolean fail = false;
public static void warn(String msg) {
if (fail) {
throw new IllegalStateException(msg);
}
log.warn(msg);
}
public static void setFail(boolean fail) {
ExceptionUtils.fail = fail;
}
}

View File

@@ -1,5 +1,14 @@
package org.springframework.cloud.sleuth.instrument.web;
import static org.assertj.core.api.BDDAssertions.then;
import static org.springframework.test.web.servlet.request.MockMvcRequestBuilders.asyncDispatch;
import static org.springframework.test.web.servlet.result.MockMvcResultMatchers.status;
import java.util.Random;
import java.util.concurrent.CompletableFuture;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
@@ -14,21 +23,34 @@ import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
import org.springframework.test.web.servlet.MvcResult;
import org.springframework.test.web.servlet.request.MockMvcRequestBuilders;
import org.springframework.test.web.servlet.setup.DefaultMockMvcBuilder;
import java.util.Random;
import static org.assertj.core.api.BDDAssertions.then;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
@RunWith(SpringJUnit4ClassRunner.class)
@SpringApplicationConfiguration(TraceFilterIntegrationTests.class)
@DefaultTestAutoConfiguration
@RestController
public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
private static Log logger = LogFactory.getLog(TraceFilterIntegrationTests.class);
@Autowired
Tracer tracer;
@Autowired
TraceKeys traceKeys;
@RequestMapping("/ping")
public String ping() {
logger.info("ping");
return "ping";
}
@RequestMapping("/future")
public CompletableFuture<String> future() {
logger.info("future");
return CompletableFuture.completedFuture("ping");
}
@Test
public void should_create_and_return_trace_in_HTTP_header() throws Exception {
MvcResult mvcResult = whenSentPingWithoutTracingData();
@@ -46,6 +68,18 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
then(tracingHeaderFrom(mvcResult)).isEqualTo(expectedTraceId);
}
@Test
public void when_correlationId_is_sent_to_async_endpoint_span_is_joined()
throws Exception {
Long expectedTraceId = new Random().nextLong();
MvcResult mvcResult = whenSentFutureWithTraceId(expectedTraceId);
mvcResult = this.mockMvc.perform(asyncDispatch(mvcResult)).andExpect(status().isOk())
.andReturn();
then(tracingHeaderFrom(mvcResult)).isEqualTo(expectedTraceId);
}
@Override
protected void configureMockMvcBuilder(DefaultMockMvcBuilder mockMvcBuilder) {
mockMvcBuilder.addFilters(new TraceFilter(this.tracer, this.traceKeys));
@@ -57,16 +91,24 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
.andReturn();
}
private MvcResult whenSentPingWithTraceId(Long passedTraceId)
throws Exception {
private MvcResult whenSentPingWithTraceId(Long passedTraceId) throws Exception {
return sendPingWithTraceId(Span.TRACE_ID_NAME, passedTraceId);
}
private MvcResult sendPingWithTraceId(String headerName, Long passedCorrelationId)
private MvcResult whenSentFutureWithTraceId(Long passedTraceId) throws Exception {
return sendPingWithTraceId("/future", Span.TRACE_ID_NAME, passedTraceId);
}
private MvcResult sendPingWithTraceId(String headerName, Long correlationId)
throws Exception {
return sendPingWithTraceId("/ping", headerName, correlationId);
}
private MvcResult sendPingWithTraceId(String path, String headerName,
Long correlationId) throws Exception {
return this.mockMvc
.perform(MockMvcRequestBuilders.get("/ping").accept(MediaType.TEXT_PLAIN)
.header(headerName, Span.toHex(passedCorrelationId))
.perform(MockMvcRequestBuilders.get(path).accept(MediaType.TEXT_PLAIN)
.header(headerName, Span.toHex(correlationId))
.header(Span.SPAN_ID_NAME, Span.toHex(new Random().nextLong())))
.andReturn();
}

View File

@@ -2,8 +2,9 @@ package org.springframework.cloud.sleuth.instrument.web.common;
import org.junit.Before;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.WebIntegrationTest;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.context.ApplicationContext;
import org.springframework.test.context.web.WebAppConfiguration;
import org.springframework.test.web.servlet.MockMvc;
import org.springframework.test.web.servlet.setup.DefaultMockMvcBuilder;
import org.springframework.test.web.servlet.setup.MockMvcBuilders;
@@ -19,15 +20,16 @@ import org.springframework.web.context.WebApplicationContext;
*
* @author 4financeIT
*/
@WebIntegrationTest(randomPort = true)
@WebAppConfiguration
public abstract class AbstractMvcIntegrationTest {
@Autowired protected WebApplicationContext webApplicationContext;
@Autowired protected ApplicationContext applicationContext;
@Autowired
protected WebApplicationContext webApplicationContext;
protected MockMvc mockMvc;
@Before
public void setup() {
ExceptionUtils.setFail(true);
DefaultMockMvcBuilder mockMvcBuilder = MockMvcBuilders.webAppContextSetup(this.webApplicationContext);
configureMockMvcBuilder(mockMvcBuilder);
this.mockMvc = mockMvcBuilder.build();