From 92bcae68f358cb1f0e175be3f7a6ab51526ee3bc Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Tue, 31 Jan 2017 15:57:22 +0100 Subject: [PATCH] Fixing the moment when SS is set (#505) without this change there's a problem with the time when the SS is set on a span. Currently it's done in TraceFilter's finally block. The problem is that this code is executed after the response has been sent back to the client. Thus CR sometimes was set faster than SS (it doesn't make any sense from the logical point of view). with this change we're introducing wrappers over the HttpServletResponse where we annotate the span with SS just after the response gets sent to the recipient. fixes #492 #431 --- .../sleuth/instrument/web/TraceFilter.java | 253 +++++++++++++++++- .../web/client/TraceAsyncRestTemplate.java | 11 + .../client/TraceRestTemplateInterceptor.java | 2 +- .../web/client/feign/TraceFeignClient.java | 1 + .../sleuth/assertions/ListOfSpansAssert.java | 140 +++++++++- .../exception/WebClientExceptionTests.java | 8 + .../web/client/feign/FeignRetriesTests.java | 1 - .../client/feign/TraceFeignClientTests.java | 1 - .../client/integration/WebClientTests.java | 20 +- 9 files changed, 421 insertions(+), 16 deletions(-) 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 86156f84a..488dd39af 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 @@ -16,17 +16,22 @@ 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; @@ -134,14 +139,15 @@ 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)) { - processErrorRequest(filterChain, request, response, spanFromRequest); + Span parentSpan = spanFromRequest != null ? spanFromRequest.getSavedSpan() : null; + processErrorRequest(filterChain, request, new TraceHttpServletResponse(response, parentSpan), spanFromRequest); return; } String name = HTTP_COMPONENT + ":" + uri; Throwable exception = null; try { spanFromRequest = createSpan(request, skip, spanFromRequest, name); - filterChain.doFilter(request, response); + filterChain.doFilter(request, new TraceHttpServletResponse(response, spanFromRequest)); } catch (Throwable e) { exception = e; this.tracer.addTag(Span.SPAN_ERROR_TAG_NAME, ExceptionUtils.getExceptionMessage(e)); @@ -163,7 +169,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); @@ -243,10 +249,7 @@ 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); } } @@ -370,3 +373,241 @@ 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); + } +} \ No newline at end of file diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceAsyncRestTemplate.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceAsyncRestTemplate.java index 8543f0849..097b87f67 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceAsyncRestTemplate.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceAsyncRestTemplate.java @@ -16,8 +16,11 @@ 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; @@ -89,6 +92,8 @@ public class TraceAsyncRestTemplate extends AsyncRestTemplate { private static class TraceListenableFutureCallback implements ListenableFutureCallback { + private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + private final Tracer tracer; private final Span parent; @@ -99,6 +104,9 @@ 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(); @@ -106,6 +114,9 @@ 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(); } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptor.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptor.java index ce71beb84..5c7cc9c3e 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptor.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptor.java @@ -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)); - this.tracer.close(currentSpan()); + finish(); throw e; } } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java index 64fc0d182..3de4e78a9 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClient.java @@ -90,6 +90,7 @@ class TraceFeignClient implements Client { logCr(); return response; } catch (RuntimeException | IOException e) { + logCr(); logError(e); throw e; } finally { 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 b1e237d75..a0b557403 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,9 +16,7 @@ package org.springframework.cloud.sleuth.assertions; -import com.fasterxml.jackson.core.JsonProcessingException; -import com.fasterxml.jackson.databind.ObjectMapper; - +import java.lang.invoke.MethodHandles; import java.util.ArrayList; import java.util.HashMap; import java.util.List; @@ -29,6 +27,9 @@ 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; @@ -142,6 +143,28 @@ public class ListOfSpansAssert extends AbstractAssert(this.actual.spans))); @@ -155,4 +178,115 @@ public class ListOfSpansAssert extends AbstractAssert 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 + '}'; + } } \ No newline at end of file diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java index dac57ca0e..b6d781a8e 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/exception/WebClientExceptionTests.java @@ -42,8 +42,10 @@ 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; @@ -86,6 +88,7 @@ public class WebClientExceptionTests { @Autowired TestFeignInterfaceWithException testFeignInterfaceWithException; @Autowired @LoadBalanced RestTemplate template; @Autowired Tracer tracer; + @Autowired ArrayListSpanAccumulator accumulator; @Before public void open() { @@ -120,6 +123,7 @@ 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() { @@ -155,6 +159,10 @@ public class WebClientExceptionTests { Sampler alwaysSampler() { return new AlwaysSampler(); } + + @Bean ArrayListSpanAccumulator accumulator() { + return new ArrayListSpanAccumulator(); + } } @Configuration diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java index daaf6fba4..ff83f8490 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/FeignRetriesTests.java @@ -132,7 +132,6 @@ 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); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java index ce8f7ea21..fd1476e5c 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/feign/TraceFeignClientTests.java @@ -98,7 +98,6 @@ 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"); } 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 c587a1196..096f88756 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 @@ -49,6 +49,7 @@ 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; @@ -111,8 +112,9 @@ public class WebClientTests { then(getHeader(response, Span.TRACE_ID_NAME)).isNull(); then(getHeader(response, Span.SPAN_ID_NAME)).isNull(); - then(this.listener.getSpans()).isNotEmpty(); - Optional noTraceSpan = new ArrayList<>(this.listener.getSpans()).stream().filter(span -> + List spans = new ArrayList<>(this.listener.getSpans()); + then(spans).isNotEmpty(); + Optional noTraceSpan = new ArrayList<>(spans).stream().filter(span -> "http:/notrace".equals(span.getName()) && !span.tags().isEmpty() && span.tags().containsKey("http.path")).findFirst(); then(noTraceSpan.isPresent()).isTrue(); @@ -120,13 +122,23 @@ 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.template - .getForEntity("http://fooservice/notrace", String.class)); + (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)); } @Test