From b5ba1c00db8be89295bdb7017e6dbad989a2fa80 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Mon, 11 Apr 2016 15:24:49 +0200 Subject: [PATCH] Stopping parent before reporting The problem resulted in wrong span durations. The issue was such that for the case where span from request has a parent that needs to be reported we didn't stop that parent. That means that it has value of 'end' equal to 0. In that situation the duration of Span was calculated as a difference between current time and the start time. We should never report spans that have not been stopped - otherwise that stopping will take place a lot of time later. fixes #247 --- .../cloud/sleuth/instrument/web/TraceFilter.java | 1 + .../sleuth/instrument/web/TraceFilterTests.java | 14 ++++++++++++++ 2 files changed, 15 insertions(+) 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 8891edb19..61c31b697 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 @@ -138,6 +138,7 @@ public class TraceFilter extends OncePerRequestFilter { Span parent = spanFromRequest.getSavedSpan(); if (parent.isRemote()) { parent.logEvent(Span.SERVER_SEND); + parent.stop(); this.spanReporter.report(parent); } } else { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java index c8e52135e..57d4ec127 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/TraceFilterTests.java @@ -184,6 +184,20 @@ public class TraceFilterTests { assertNull(TestSpanContextHolder.getCurrentSpan()); } + @Test + public void ensuresThatParentSpanIsStoppedWhenReported() throws Exception { + this.request = builder().header(Span.SPAN_ID_NAME, 10L) + .header(Span.TRACE_ID_NAME, 20L).buildRequest(new MockServletContext()); + TraceFilter filter = new TraceFilter(this.tracer, this.traceKeys, spanIsStoppedVeryfingReporter(), + this.spanExtractor, this.spanInjector); + + filter.doFilter(this.request, this.response, this.filterChain); + } + + SpanReporter spanIsStoppedVeryfingReporter() { + return (span) -> assertThat(span.getEnd()).as("Span has to be stopped before reporting").isNotZero(); + } + @Test public void additionalMultiValuedHeader() throws Exception { this.request = builder().header(Span.SPAN_ID_NAME, 10L)