Fixing the moment when SS is set

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/SsLogSetter.java

@@ -0,0 +1,51 @@
+/*
+ * Copyright 2013-2016 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.springframework.cloud.sleuth.instrument.web;
+
+import java.lang.invoke.MethodHandles;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+
+/**
+ * Utility class to set SS log if it wasn't already set
+ *
+ * @author Marcin Grzejszczak
+ */
+class SsLogSetter {
+
+	private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
+
+	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())) {
+				if (log.isTraceEnabled()) {
+					log.trace("Span was already annotated with SS, will not do it again");
+				}
+				return;
+			}
+		}
+		if (log.isTraceEnabled()) {
+			log.trace("Will set SS on the span");
+		}
+		span.logEvent(Span.SERVER_SEND);
+	}
+}

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

@@ -134,14 +134,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 = parentSpan(spanFromRequest);
+			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));
@@ -159,11 +160,21 @@ public class TraceFilter extends GenericFilterBean {
 		}
 	}
 
+	private Span parentSpan(Span span) {
+		if (span == null) {
+			return null;
+		}
+		if (span.hasSavedSpan()) {
+			return span.getSavedSpan();
+		}
+		return span;
+	}
+
 	private void processErrorRequest(FilterChain filterChain, HttpServletRequest request,
 			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 +254,12 @@ public class TraceFilter extends GenericFilterBean {
 				log.debug("Trying to send the parent span " + parent + " to Zipkin");
 			}
 			parent.stop();
-			parent.logEvent(Span.SERVER_SEND);
+			// should be already done by HttpServletResponse wrappers
+			SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(parent);
 			this.spanReporter.report(parent);
 		} else {
-			parent.logEvent(Span.SERVER_SEND);
+			// should be already done by HttpServletResponse wrappers
+			SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(parent);
 		}
 	}
 
@@ -375,3 +388,4 @@ public class TraceFilter extends GenericFilterBean {
 		}
 	}
 }
+

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHttpServletResponse.java

@@ -0,0 +1,60 @@
+/*
+ * Copyright 2013-2016 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.springframework.cloud.sleuth.instrument.web;
+
+import java.io.IOException;
+import java.io.PrintWriter;
+import java.lang.invoke.MethodHandles;
+import javax.servlet.ServletOutputStream;
+import javax.servlet.http.HttpServletResponse;
+import javax.servlet.http.HttpServletResponseWrapper;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+
+/**
+ * We want to set SS as fast as possible after the response was sent back. The response
+ * can be sent back by calling either an {@link ServletOutputStream} or {@link PrintWriter}.
+ */
+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");
+		}
+		SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
+		super.flushBuffer();
+	}
+
+	@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);
+	}
+}

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TracePrintWriter.java

@@ -0,0 +1,186 @@
+/*
+ * Copyright 2013-2016 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.springframework.cloud.sleuth.instrument.web;
+
+import java.io.PrintWriter;
+import java.lang.invoke.MethodHandles;
+import java.util.Locale;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+
+/**
+ * @author Marcin Grzejszczak
+ */
+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");
+		}
+		SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
+		this.delegate.flush();
+	}
+
+	@Override public void close() {
+		if (log.isTraceEnabled()) {
+			log.trace("Will annotate SS once the stream is closed");
+		}
+		SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
+		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);
+	}
+}

spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceServletOutputStream.java

@@ -0,0 +1,138 @@
+/*
+ * Copyright 2013-2016 the original author or authors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.springframework.cloud.sleuth.instrument.web;
+
+import java.io.IOException;
+import java.lang.invoke.MethodHandles;
+import javax.servlet.ServletOutputStream;
+import javax.servlet.WriteListener;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.springframework.cloud.sleuth.Span;
+
+/**
+ * @author Marcin Grzejszczak
+ */
+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 {
+		this.delegate.write(b);
+	}
+
+	@Override public void print(String s) throws IOException {
+		this.delegate.print(s);
+	}
+
+	@Override public void print(boolean b) throws IOException {
+		this.delegate.print(b);
+	}
+
+	@Override public void print(char c) throws IOException {
+		this.delegate.print(c);
+	}
+
+	@Override public void print(int i) throws IOException {
+		this.delegate.print(i);
+	}
+
+	@Override public void print(long l) throws IOException {
+		this.delegate.print(l);
+	}
+
+	@Override public void print(float f) throws IOException {
+		this.delegate.print(f);
+	}
+
+	@Override public void print(double d) throws IOException {
+		this.delegate.print(d);
+	}
+
+	@Override public void println() throws IOException {
+		this.delegate.println();
+	}
+
+	@Override public void println(String s) throws IOException {
+		this.delegate.println(s);
+	}
+
+	@Override public void println(boolean b) throws IOException {
+		this.delegate.println(b);
+	}
+
+	@Override public void println(char c) throws IOException {
+		this.delegate.println(c);
+	}
+
+	@Override public void println(int i) throws IOException {
+		this.delegate.println(i);
+	}
+
+	@Override public void println(long l) throws IOException {
+		this.delegate.println(l);
+	}
+
+	@Override public void println(float f) throws IOException {
+		this.delegate.println(f);
+	}
+
+	@Override public void println(double d) throws IOException {
+		this.delegate.println(d);
+	}
+
+	@Override public void write(byte[] b) throws IOException {
+		this.delegate.write(b);
+	}
+
+	@Override public void write(byte[] b, int off, int len) throws IOException {
+		this.delegate.write(b, off, len);
+	}
+
+	@Override public void flush() throws IOException {
+		if (log.isTraceEnabled()) {
+			log.trace("Will annotate SS once the stream is flushed");
+		}
+		SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
+		this.delegate.flush();
+	}
+
+	@Override public void close() throws IOException {
+		if (log.isTraceEnabled()) {
+			log.trace("Will annotate SS once the stream is closed");
+		}
+		SsLogSetter.annotateWithServerSendIfLogIsNotAlreadyPresent(this.span);
+		this.delegate.close();
+	}
+}

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

@@ -91,6 +91,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,6 +16,7 @@
 
 package org.springframework.cloud.sleuth.assertions;
 
+import java.lang.invoke.MethodHandles;
 import java.util.ArrayList;
 import java.util.HashMap;
 import java.util.List;
@@ -252,6 +253,39 @@ 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 hasServerSideSpansInProperOrder() {
+		isNotNull();
+		printSpans();
+		RpcLogKeeper rpcLogKeeper = findRpcLogs();
+		log.info("Rpc logs [" + rpcLogKeeper.toString() + "]");
+		rpcLogKeeper.assertThatServerSideEventsBelongToSameTraceAndSpan();
+		rpcLogKeeper.assertThatServerSideEventsTookPlace();
+		rpcLogKeeper.assertThatServerLogsTookPlaceInOrder();
+		return this;
+	}
+
+	public ListOfSpansAssert hasRpcWithoutSeverSideDueToException() {
+		isNotNull();
+		printSpans();
+		RpcLogKeeper rpcLogKeeper = findRpcLogs();
+		log.info("Rpc logs [" + rpcLogKeeper.toString() + "]");
+		rpcLogKeeper.assertThatClientSideEventsBelongToSameTraceAndSpan();
+		rpcLogKeeper.assertThatClientSideEventsTookPlace();
+		rpcLogKeeper.assertThatClientLogsTookPlaceInOrder();
+		return this;
+	}
+
 	private void printSpans() {
 		log.info("Stored spans " + spansToString());
 	}
@@ -261,4 +295,130 @@ 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() {
+		assertThatServerSideEventsTookPlace();
+		assertThatClientSideEventsTookPlace();
+	}
+	void assertThatServerSideEventsTookPlace() {
+		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");
+	}
+
+	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 assertThatClientSideEventsBelongToSameTraceAndSpan() {
+		log.info("Checking if CR/CS logs 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 logs have the same trace id");
+		assertThat(this.csTraceId).describedAs("All logs should come from the same trace").isEqualTo(this.crTraceId);
+	}
+
+	void assertThatServerSideEventsBelongToSameTraceAndSpan() {
+		log.info("Checking if SS/SR logs are coming from the same span");
+		assertThat(this.ssSpanId).describedAs("All logs should come from the same span").isEqualTo(this.srSpanId);
+		log.info("Checking if SS/SR logs have the same trace id");
+		assertThat(this.ssTraceId).describedAs("All logs should come from the same trace").isEqualTo(this.srTraceId);
+	}
+
+	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 assertThatClientLogsTookPlaceInOrder() {
+		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);
+	}
+
+	void assertThatServerLogsTookPlaceInOrder() {
+		long srTimestamp = this.sr.getTimestamp();
+		long ssTimestamp = this.ss.getTimestamp();
+		log.info("Checking if CS is before CR");
+		assertThat(srTimestamp).as("SR timestamp should be before SS timestamp").isLessThanOrEqualTo(ssTimestamp);
+	}
+
+	@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/SpringDataInstrumentationTests.java

@@ -92,6 +92,7 @@ public class SpringDataInstrumentationTests {
 		});
 		then(this.tracer.getCurrentSpan()).isNull();
 		then(ExceptionUtils.getLastException()).isNull();
+		then(new ListOfSpans(this.arrayListSpanAccumulator.getSpans())).hasRpcTagsInProperOrder();
 	}
 
 	Collection<String> names() {

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java

@@ -19,6 +19,7 @@ import org.springframework.cloud.sleuth.Span;
 import org.springframework.cloud.sleuth.SpanReporter;
 import org.springframework.cloud.sleuth.TraceKeys;
 import org.springframework.cloud.sleuth.Tracer;
+import org.springframework.cloud.sleuth.assertions.ListOfSpans;
 import org.springframework.cloud.sleuth.instrument.DefaultTestAutoConfiguration;
 import org.springframework.cloud.sleuth.instrument.web.common.AbstractMvcIntegrationTest;
 import org.springframework.cloud.sleuth.sampler.AlwaysSampler;
@@ -69,6 +70,7 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
 				.hasATagWithKey(new TraceKeys().getMvc().getControllerMethod())
 				.hasLoggedAnEvent(Span.SERVER_SEND);
 		then(ExceptionUtils.getLastException()).isNull();
+		then(new ListOfSpans(this.spanAccumulator.getSpans())).hasServerSideSpansInProperOrder();
 	}
 
 	@Test
@@ -129,6 +131,7 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
 		then(taggedSpan.get()).hasATag("mvc.controller.method", "deferredMethod");
 		then(taggedSpan.get()).hasATag("mvc.controller.class", "TestController");
 		then(ExceptionUtils.getLastException()).isNull();
+		then(new ListOfSpans(this.spanAccumulator.getSpans())).hasServerSideSpansInProperOrder();
 	}
 
 	@Test
@@ -152,6 +155,7 @@ public class TraceFilterIntegrationTests extends AbstractMvcIntegrationTest {
 				span.getSpanId() == span.getTraceId()).findAny().isPresent()).as("a root span exists").isTrue();
 		then(this.tracer.getCurrentSpan()).isNull();
 		then(ExceptionUtils.getLastException()).isNull();
+		then(new ListOfSpans(this.spanAccumulator.getSpans())).hasServerSideSpansInProperOrder();
 	}
 
 	@Override

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java

@@ -76,7 +76,8 @@ public class TraceFilterWebIntegrationTests {
 		then(ExceptionUtils.getLastException()).isNull();
 		then(new ListOfSpans(this.accumulator.getSpans()))
 				.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
-						"Request processing failed; nested exception is java.lang.RuntimeException: Throwing exception");
+						"Request processing failed; nested exception is java.lang.RuntimeException: Throwing exception")
+				.hasRpcTagsInProperOrder();
 	}
 
 	private int port() {

spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptorIntegrationTests.java

@@ -96,8 +96,8 @@ public class TraceRestTemplateInterceptorIntegrationTests {
 		SleuthAssertions.then(this.tracer.getCurrentSpan()).isEqualTo(span);
 		this.tracer.close(span);
 		SleuthAssertions.then(new ListOfSpans(this.spanAccumulator.getSpans()))
-				.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME,
-						"Read timed out");
+				.hasASpanWithTagEqualTo(Span.SPAN_ERROR_TAG_NAME, "Read timed out")
+				.hasRpcWithoutSeverSideDueToException();
 		then(ExceptionUtils.getLastException()).isNull();
 	}
 

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

@@ -21,10 +21,6 @@ import java.lang.invoke.MethodHandles;
 import java.util.Collections;
 import java.util.Map;
 
-import com.netflix.loadbalancer.BaseLoadBalancer;
-import com.netflix.loadbalancer.ILoadBalancer;
-import com.netflix.loadbalancer.Server;
-
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 import org.junit.After;
@@ -45,8 +41,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;
@@ -59,6 +57,10 @@ import org.springframework.web.bind.annotation.RequestMapping;
 import org.springframework.web.bind.annotation.RequestMethod;
 import org.springframework.web.client.RestTemplate;
 
+import com.netflix.loadbalancer.BaseLoadBalancer;
+import com.netflix.loadbalancer.ILoadBalancer;
+import com.netflix.loadbalancer.Server;
+
 import junitparams.JUnitParamsRunner;
 import junitparams.Parameters;
 
@@ -66,10 +68,10 @@ import static junitparams.JUnitParamsRunner.$;
 import static org.springframework.cloud.sleuth.assertions.SleuthAssertions.then;
 
 @RunWith(JUnitParamsRunner.class)
-@SpringBootTest(classes = WebClientExceptionTests.TestConfiguration.class,
+@SpringBootTest(classes = {
+		WebClientExceptionTests.TestConfiguration.class },
+		properties = {"ribbon.ConnectTimeout=30000", "spring.application.name=exceptionservice" },
 		webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT)
-@TestPropertySource(properties = {"ribbon.ConnectTimeout=30000",
-		"spring.application.name=exceptionservice" })
 public class WebClientExceptionTests {
 
 	private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass());
@@ -84,6 +86,7 @@ public class WebClientExceptionTests {
 	@Autowired TestFeignInterfaceWithException testFeignInterfaceWithException;
 	@Autowired @LoadBalanced RestTemplate template;
 	@Autowired Tracer tracer;
+	@Autowired ArrayListSpanAccumulator accumulator;
 
 	@Before
 	public void open() {
@@ -117,6 +120,7 @@ public class WebClientExceptionTests {
 		this.tracer.close(span);
 		then(ExceptionUtils.getLastException()).isNull();
 		then(this.capture.toString()).doesNotContain("Tried to detach trace span but it is not the current span");
+		then(new ListOfSpans(this.accumulator.getSpans())).hasRpcWithoutSeverSideDueToException();
 	}
 
 	Object[] parametersForShouldCloseSpanUponException() {
@@ -152,6 +156,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

@@ -136,7 +136,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

@@ -102,7 +102,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

@@ -24,6 +24,7 @@ import java.util.List;
 import java.util.Map;
 import java.util.Optional;
 import java.util.Random;
+import java.util.concurrent.TimeUnit;
 import java.util.stream.Collectors;
 import javax.servlet.http.HttpServletRequest;
 
@@ -49,6 +50,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;
@@ -67,6 +69,7 @@ import org.springframework.web.bind.annotation.RestController;
 import org.springframework.web.client.HttpClientErrorException;
 import org.springframework.web.client.RestTemplate;
 
+import com.jayway.awaitility.Awaitility;
 import com.netflix.loadbalancer.BaseLoadBalancer;
 import com.netflix.loadbalancer.ILoadBalancer;
 import com.netflix.loadbalancer.Server;
@@ -111,24 +114,40 @@ public class WebClientTests {
 			ResponseEntityProvider provider) {
 		ResponseEntity<String> response = provider.get(this);
 
-		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 ->
-				"http:/notrace".equals(span.getName()) && !span.tags().isEmpty()
-						&& span.tags().containsKey("http.path")).findFirst();
-		then(noTraceSpan.isPresent()).isTrue();
-		// TODO: matches cause there is an issue with Feign not providing the full URL at the interceptor level
-		then(noTraceSpan.get()).matchesATag("http.url", ".*/notrace")
-				.hasATag("http.path", "/notrace")
-				.hasATag("http.method", "GET");
+		Awaitility.await().atMost(2, TimeUnit.SECONDS).until(() -> {
+			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 -> "http:/notrace".equals(span.getName()) && !span.tags()
+							.isEmpty() && span.tags().containsKey("http.path")).findFirst();
+			then(noTraceSpan.isPresent()).isTrue();
+			// TODO: matches cause there is an issue with Feign not providing the full URL at the interceptor level
+			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.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),
+				(ResponseEntityProvider) (tests) -> tests.template.getForEntity("http://fooservice/notrace", String.class));
 	}
 
 	@Test