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

Revert "Fixing the moment when SS is set (#505)"

Browse Source 
This reverts commit 92bcae68f3.
This commit is contained in:
Marcin Grzejszczak
2017-01-31 16:20:31 +01:00
parent 92bcae68f3
commit 5c117534aa
9 changed files with 16 additions and 421 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -16,22 +16,17 @@
package org.springframework.cloud.sleuth.instrument.web;
import java.io.IOException;
import java.io.PrintWriter;
import java.lang.invoke.MethodHandles;
import java.util.ArrayList;
import java.util.Collections;
import java.util.Enumeration;
import java.util.Locale;
import java.util.regex.Pattern;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.ServletOutputStream;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.WriteListener;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import javax.servlet.http.HttpServletResponseWrapper;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
@@ -139,15 +134,14 @@ public class TraceFilter extends GenericFilterBean {
}
// in case of a response with exception status a exception controller will close the span
if (!httpStatusSuccessful(response) && isSpanContinued(request)) {
Span parentSpan = spanFromRequest != null ? spanFromRequest.getSavedSpan() : null;
processErrorRequest(filterChain, request, new TraceHttpServletResponse(response, parentSpan), spanFromRequest);
processErrorRequest(filterChain, request, response, spanFromRequest);
return;
}
String name = HTTP_COMPONENT + ":" + uri;
Throwable exception = null;
try {
spanFromRequest = createSpan(request, skip, spanFromRequest, name);
filterChain.doFilter(request, new TraceHttpServletResponse(response, spanFromRequest));
filterChain.doFilter(request, response);
} catch (Throwable e) {
exception = e;
this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e));
@@ -169,7 +163,7 @@ public class TraceFilter extends GenericFilterBean {
HttpServletResponse response, Span spanFromRequest)
throws IOException, ServletException {
if (log.isDebugEnabled()) {
log.debug("The span " + spanFromRequest + " was already detached once and we're processing an error");
log.debug("The span [" + spanFromRequest + "] was already detached once and we're processing an error");
}
try {
filterChain.doFilter(request, response);
@@ -249,7 +243,10 @@ public class TraceFilter extends GenericFilterBean {
log.debug("Trying to send the parent span " + parent + " to Zipkin");
}
parent.stop();
parent.logEvent(Span.SERVER_SEND);
this.spanReporter.report(parent);
} else {
parent.logEvent(Span.SERVER_SEND);
}
}
@@ -373,241 +370,3 @@ public class TraceFilter extends GenericFilterBean {
}
}
}
/**
* We want to set SS as fast as possible after the response was sent back. The response
* can be sent back by calling either of these methods.
*/
class TraceHttpServletResponse extends HttpServletResponseWrapper {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
private final Span span;
TraceHttpServletResponse(HttpServletResponse response, Span span) {
super(response);
this.span = span;
}
@Override public void flushBuffer() throws IOException {
if (log.isTraceEnabled()) {
log.trace("Will annotate SS once the response is flushed");
}
try {
super.flushBuffer();
} finally {
SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
}
}
@Override public ServletOutputStream getOutputStream() throws IOException {
return new TraceServletOutputStream(super.getOutputStream(), this.span);
}
@Override public PrintWriter getWriter() throws IOException {
return new TracePrintWriter(super.getWriter(), this.span);
}
}
class TraceServletOutputStream extends ServletOutputStream {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
private final ServletOutputStream delegate;
private final Span span;
TraceServletOutputStream(ServletOutputStream delegate, Span span) {
this.delegate = delegate;
this.span = span;
}
@Override public boolean isReady() {
return this.delegate.isReady();
}
@Override public void setWriteListener(WriteListener listener) {
this.delegate.setWriteListener(listener);
}
@Override public void write(int b) throws IOException {
if (log.isTraceEnabled()) {
log.trace("Will annotate SS once the response is flushed");
}
try {
this.delegate.write(b);
} finally {
SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
}
}
}
class TracePrintWriter extends PrintWriter {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
private final PrintWriter delegate;
private final Span span;
TracePrintWriter(PrintWriter delegate, Span span) {
super(delegate);
this.delegate = delegate;
this.span = span;
}
@Override public void flush() {
if (log.isTraceEnabled()) {
log.trace("Will annotate SS once the response is flushed");
}
try {
this.delegate.flush();
} finally {
SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
}
}
@Override public void close() {
this.delegate.close();
}
@Override public boolean checkError() {
return this.delegate.checkError();
}
@Override public void write(int c) {
this.delegate.write(c);
}
@Override public void write(char[] buf, int off, int len) {
this.delegate.write(buf, off, len);
}
@Override public void write(char[] buf) {
this.delegate.write(buf);
}
@Override public void write(String s, int off, int len) {
this.delegate.write(s, off, len);
}
@Override public void write(String s) {
this.delegate.write(s);
}
@Override public void print(boolean b) {
this.delegate.print(b);
}
@Override public void print(char c) {
this.delegate.print(c);
}
@Override public void print(int i) {
this.delegate.print(i);
}
@Override public void print(long l) {
this.delegate.print(l);
}
@Override public void print(float f) {
this.delegate.print(f);
}
@Override public void print(double d) {
this.delegate.print(d);
}
@Override public void print(char[] s) {
this.delegate.print(s);
}
@Override public void print(String s) {
this.delegate.print(s);
}
@Override public void print(Object obj) {
this.delegate.print(obj);
}
@Override public void println() {
this.delegate.println();
}
@Override public void println(boolean x) {
this.delegate.println(x);
}
@Override public void println(char x) {
this.delegate.println(x);
}
@Override public void println(int x) {
this.delegate.println(x);
}
@Override public void println(long x) {
this.delegate.println(x);
}
@Override public void println(float x) {
this.delegate.println(x);
}
@Override public void println(double x) {
this.delegate.println(x);
}
@Override public void println(char[] x) {
this.delegate.println(x);
}
@Override public void println(String x) {
this.delegate.println(x);
}
@Override public void println(Object x) {
this.delegate.println(x);
}
@Override public PrintWriter printf(String format, Object... args) {
return this.delegate.printf(format, args);
}
@Override public PrintWriter printf(Locale l, String format, Object... args) {
return this.delegate.printf(l, format, args);
}
@Override public PrintWriter format(String format, Object... args) {
return this.delegate.format(format, args);
}
@Override public PrintWriter format(Locale l, String format, Object... args) {
return this.delegate.format(l, format, args);
}
@Override public PrintWriter append(CharSequence csq) {
return this.delegate.append(csq);
}
@Override public PrintWriter append(CharSequence csq, int start, int end) {
return this.delegate.append(csq, start, end);
}
@Override public PrintWriter append(char c) {
return this.delegate.append(c);
}
}
class SsLogSetter {
static void annotateWithServerSendIfLogIsNotAlreadyPresent(Span span) {
if (span == null) {
return;
}
for (org.springframework.cloud.sleuth.Log log1 : span.logs()) {
if (Span.SERVER_SEND.equals(log1.getEvent())) {
return;
}
}
span.logEvent(Span.SERVER_SEND);
}
}

11
spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceAsyncRestTemplate.java
View File

@@ -16,11 +16,8 @@
package org.springframework.cloud.sleuth.instrument.web.client;
import java.lang.invoke.MethodHandles;
import java.net.URI;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.cloud.sleuth.Span;
import org.springframework.cloud.sleuth.Tracer;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
@@ -92,8 +89,6 @@ public class TraceAsyncRestTemplate extends AsyncRestTemplate {
private static class TraceListenableFutureCallback<T> implements ListenableFutureCallback<T> {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
private final Tracer tracer;
private final Span parent;
@@ -104,9 +99,6 @@ public class TraceAsyncRestTemplate extends AsyncRestTemplate {
@Override
public void onFailure(Throwable ex) {
if (log.isDebugEnabled()) {
log.debug("The callback failed - will close the span");
}
continueSpan();
this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(ex));
finish();
@@ -114,9 +106,6 @@ public class TraceAsyncRestTemplate extends AsyncRestTemplate {
@Override
public void onSuccess(T result) {
if (log.isDebugEnabled()) {
log.debug("The callback succeeded - will close the span");
}
continueSpan();
finish();
}

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

@@ -62,7 +62,7 @@ public class TraceRestTemplateInterceptor extends AbstractTraceHttpRequestInterc
log.debug("Exception occurred while trying to execute the request. Will close the span [" + currentSpan() + "]", e);
}
this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e));
finish();
this.tracer.close(currentSpan());
throw e;
}
}

1
spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java
View File

@@ -90,7 +90,6 @@ class TraceFeignClient implements Client {
logCr();
return response;
} catch (RuntimeException | IOException e) {
logCr();
logError(e);
throw e;
} finally {

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

@@ -16,7 +16,9 @@
package org.springframework.cloud.sleuth.assertions;
import java.lang.invoke.MethodHandles;
import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;
import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
@@ -27,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;
@@ -143,28 +142,6 @@ public class ListOfSpansAssert extends AbstractAssert<ListOfSpansAssert, ListOfS
return this;
}
public ListOfSpansAssert hasRpcTagsInProperOrder() {
isNotNull();
printSpans();
RpcLogKeeper rpcLogKeeper = findRpcLogs();
log.info("Rpc logs [" + rpcLogKeeper.toString() + "]");
rpcLogKeeper.assertThatAllBelongToSameTraceAndSpan();
rpcLogKeeper.assertThatFullRpcCycleTookPlace();
rpcLogKeeper.assertThatRpcLogsTookPlaceInOrder();
return this;
}
public ListOfSpansAssert hasRpcWithoutSeverSideDueToException() {
isNotNull();
printSpans();
RpcLogKeeper rpcLogKeeper = findRpcLogs();
log.info("Rpc logs [" + rpcLogKeeper.toString() + "]");
rpcLogKeeper.assertThatAllButBelongToSameTraceAndSpan();
rpcLogKeeper.assertThatClientSideEventsTookPlace();
rpcLogKeeper.assertThatCliendLogsTookPlaceInOrder();
return this;
}
private void printSpans() {
try {
log.info("Stored spans " + this.objectMapper.writeValueAsString(new ArrayList<>(this.actual.spans)));
@@ -178,115 +155,4 @@ public class ListOfSpansAssert extends AbstractAssert<ListOfSpansAssert, ListOfS
log.error(String.format(errorMessage, arguments));
super.failWithMessage(errorMessage, arguments);
}
RpcLogKeeper findRpcLogs() {
final RpcLogKeeper rpcLogKeeper = new RpcLogKeeper();
this.actual.spans.forEach(span -> span.logs().forEach(log -> {
switch (log.getEvent()) {
case Span.CLIENT_SEND:
rpcLogKeeper.cs = log;
rpcLogKeeper.csSpanId = span.getSpanId();
rpcLogKeeper.csTraceId = span.getTraceId();
break;
case Span.SERVER_RECV:
rpcLogKeeper.sr = log;
rpcLogKeeper.srSpanId = span.getSpanId();
rpcLogKeeper.srTraceId = span.getTraceId();
break;
case Span.SERVER_SEND:
rpcLogKeeper.ss = log;
rpcLogKeeper.ssSpanId = span.getSpanId();
rpcLogKeeper.ssTraceId = span.getTraceId();
break;
case Span.CLIENT_RECV:
rpcLogKeeper.cr = log;
rpcLogKeeper.crSpanId = span.getSpanId();
rpcLogKeeper.crTraceId = span.getTraceId();
break;
default:
break;
}
}));
return rpcLogKeeper;
}
}
class RpcLogKeeper {
private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
org.springframework.cloud.sleuth.Log cs;
long csSpanId;
long csTraceId;
org.springframework.cloud.sleuth.Log sr;
long srSpanId;
long srTraceId;
org.springframework.cloud.sleuth.Log ss;
long ssSpanId;
long ssTraceId;
org.springframework.cloud.sleuth.Log cr;
long crSpanId;
long crTraceId;
void assertThatFullRpcCycleTookPlace() {
log.info("Checking if Client Send took place");
assertThat(this.cs).describedAs("Client Send log").isNotNull();
log.info("Checking if Server Received took place");
assertThat(this.sr).describedAs("Server Received log").isNotNull();
log.info("Checking if Server Send took place");
assertThat(this.ss).describedAs("Server Send log").isNotNull();
log.info("Checking if Client Received took place");
assertThat(this.cr).describedAs("Client Received log").isNotNull();
}
void assertThatClientSideEventsTookPlace() {
log.info("Checking if Client Send took place");
assertThat(this.cs).describedAs("Client Send log").isNotNull();
log.info("Checking if Client Received took place");
assertThat(this.cr).describedAs("Client Received log").isNotNull();
}
void assertThatAllBelongToSameTraceAndSpan() {
log.info("Checking if RPC spans are coming from the same span");
assertThat(this.csSpanId).describedAs("All logs should come from the same span")
.isEqualTo(this.srSpanId).isEqualTo(this.ssSpanId).isEqualTo(this.crSpanId);
log.info("Checking if RPC spans have the same trace id");
assertThat(this.csTraceId).describedAs("All logs should come from the same trace")
.isEqualTo(this.srTraceId).isEqualTo(this.ssTraceId).isEqualTo(this.crTraceId);
}
void assertThatAllButBelongToSameTraceAndSpan() {
log.info("Checking if CR/CS spans are coming from the same span");
assertThat(this.csSpanId).describedAs("All logs should come from the same span").isEqualTo(this.crSpanId);
log.info("Checking if CR/CS spans have the same trace id");
assertThat(this.csTraceId).describedAs("All logs should come from the same trace").isEqualTo(this.crTraceId);
}
void assertThatRpcLogsTookPlaceInOrder() {
long csTimestamp = this.cs.getTimestamp();
long srTimestamp = this.sr.getTimestamp();
long ssTimestamp = this.ss.getTimestamp();
long crTimestamp = this.cr.getTimestamp();
log.info("Checking if CR is before SR");
assertThat(csTimestamp).as("CS timestamp should be before SR timestamp").isLessThanOrEqualTo(srTimestamp);
log.info("Checking if SR is before SS");
assertThat(srTimestamp).as("SR timestamp should be before SS timestamp").isLessThanOrEqualTo(ssTimestamp);
log.info("Checking if SS is before CR");
assertThat(ssTimestamp).as("SS timestamp should be before CR timestamp").isLessThanOrEqualTo(crTimestamp);
}
void assertThatCliendLogsTookPlaceInOrder() {
long csTimestamp = this.cs.getTimestamp();
long crTimestamp = this.cr.getTimestamp();
log.info("Checking if CS is before CR");
assertThat(csTimestamp).as("CS timestamp should be before CR timestamp").isLessThanOrEqualTo(crTimestamp);
}
@Override public String toString() {
return "RpcLogKeeper{" + "cs=" + cs + ", csSpanId=" + csSpanId + ", csTraceId="
+ csTraceId + ", sr=" + sr + ", srSpanId=" + srSpanId + ", srTraceId="
+ srTraceId + ", ss=" + ss + ", ssSpanId=" + ssSpanId + ", ssTraceId="
+ ssTraceId + ", cr=" + cr + ", crSpanId=" + crSpanId + ", crTraceId="
+ crTraceId + '}';
}
}

8
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java
View File

@@ -42,10 +42,8 @@ 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.ListOfSpans;
import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.trace.TestSpanContextHolder;
import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
import org.springframework.cloud.sleuth.util.ExceptionUtils;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@@ -88,7 +86,6 @@ public class WebClientExceptionTests {
@Autowired TestFeignInterfaceWithException testFeignInterfaceWithException;
@Autowired @LoadBalanced RestTemplate template;
@Autowired Tracer tracer;
@Autowired ArrayListSpanAccumulator accumulator;
@Before
public void open() {
@@ -123,7 +120,6 @@ public class WebClientExceptionTests {
then(ExceptionUtils.getLastException()).isNull();
then(this.systemErrRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span");
then(this.systemOutRule.getLog()).doesNotContain("Tried to detach trace span but it is not the current span");
then(new ListOfSpans(this.accumulator.getSpans())).hasRpcWithoutSeverSideDueToException();
}
Object[] parametersForShouldCloseSpanUponException() {
@@ -159,10 +155,6 @@ public class WebClientExceptionTests {
Sampler alwaysSampler() {
return new AlwaysSampler();
}
@Bean ArrayListSpanAccumulator accumulator() {
return new ArrayListSpanAccumulator();
}
}
@Configuration

1
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java
View File

@@ -132,6 +132,7 @@ public class FeignRetriesTests {
then(this.tracer.getCurrentSpan()).isNull();
then(ExceptionUtils.getLastException()).isNull();
then(this.spanAccumulator.getSpans().get(0))
.hasNotLoggedAnEvent(Span.CLIENT_RECV)
.hasATag("error", "java.io.IOException");
then(this.spanAccumulator.getSpans().get(1))
.hasLoggedAnEvent(Span.CLIENT_RECV);

1
spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java
View File

@@ -98,6 +98,7 @@ public class TraceFeignClientTests {
then(this.tracer.getCurrentSpan()).isEqualTo(span);
then(this.spanAccumulator.getSpans().get(0))
.hasNotLoggedAnEvent(Span.CLIENT_RECV)
.hasATag(Span.SPAN_ERROR_TAG_NAME, "exception has occurred");
}

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

@@ -49,7 +49,6 @@ 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.sampler.AlwaysSampler;
import org.springframework.cloud.sleuth.trace.TestSpanContextHolder;
import org.springframework.cloud.sleuth.util.ArrayListSpanAccumulator;
@@ -112,9 +111,8 @@ public class WebClientTests {
then(getHeader(response, Span.TRACE_ID_NAME)).isNull();
then(getHeader(response, Span.SPAN_ID_NAME)).isNull();
List<Span> spans = new ArrayList<>(this.listener.getSpans());
then(spans).isNotEmpty();
Optional<Span> noTraceSpan = new ArrayList<>(spans).stream().filter(span ->
then(this.listener.getSpans()).isNotEmpty();
Optional<Span> noTraceSpan = new ArrayList<>(this.listener.getSpans()).stream().filter(span ->
"http:/notrace".equals(span.getName()) && !span.tags().isEmpty()
&& span.tags().containsKey("http.path")).findFirst();
then(noTraceSpan.isPresent()).isTrue();
@@ -122,23 +120,13 @@ public class WebClientTests {
then(noTraceSpan.get()).matchesATag("http.url", ".*/notrace")
.hasATag("http.path", "/notrace")
.hasATag("http.method", "GET");
then(new ListOfSpans(spans)).hasRpcTagsInProperOrder();
}
Object[] parametersForShouldCreateANewSpanWithClientSideTagsWhenNoPreviousTracingWasPresent() {
return $(
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.testFeignInterface.getNoTrace(),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class),
(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class));
(ResponseEntityProvider) (tests) -> tests.template
.getForEntity("http://fooservice/notrace", String.class));
}
@Test