diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/SsLogSetter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/SsLogSetter.java new file mode 100644 index 000000000..0eefc1ab6 --- /dev/null +++ b/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); + } +} 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 3a43e5ddf..a74c2595b 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 @@ -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 { } } } + diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHttpServletResponse.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceHttpServletResponse.java new file mode 100644 index 000000000..a02d49797 --- /dev/null +++ b/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); + } +} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TracePrintWriter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TracePrintWriter.java new file mode 100644 index 000000000..96ea7855e --- /dev/null +++ b/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); + } +} diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceServletOutputStream.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/web/TraceServletOutputStream.java new file mode 100644 index 000000000..f5e4779ab --- /dev/null +++ b/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(); + } +} 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 1ff8ad087..553fa212c 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 3d83732f2..c3d4c8a6f 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 @@ -91,6 +91,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 689ea2a66..b180ad4da 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,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 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 + '}'; + } } \ No newline at end of file diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/SpringDataInstrumentationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/SpringDataInstrumentationTests.java index 923a82914..587377b47 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/SpringDataInstrumentationTests.java +++ b/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 names() { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java index 6efb641cc..feb03c1ea 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterIntegrationTests.java +++ b/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 diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java index a8df68a98..070439d20 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterWebIntegrationTests.java +++ b/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() { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptorIntegrationTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptorIntegrationTests.java index 5553f6762..f668630e2 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/client/TraceRestTemplateInterceptorIntegrationTests.java +++ b/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(); } 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 7ffba9e9a..9778af4c2 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 @@ -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 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 609855427..049187680 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 @@ -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); 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 21e98fb17..fc8a1313f 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 @@ -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"); } 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 882488d0d..936aabbc6 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 @@ -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 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 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 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(); + // 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