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

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

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<T> implements ListenableFutureCallback<T> {
 
+		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();
 		}

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

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 {

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<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)));
@@ -155,4 +178,115 @@ 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 + '}';
+	}
 }

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

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

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

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<Span> noTraceSpan = new ArrayList<>(this.listener.getSpans()).stream().filter(span ->
+		List<Span> spans = new ArrayList<>(this.listener.getSpans());
+		then(spans).isNotEmpty();
+		Optional<Span> 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