From feac9980da307e4548f03810b89a34cc2234092e Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Wed, 12 Jul 2017 18:08:43 +0200 Subject: [PATCH] Fixed not clearing trace attribute on closed span due to this Zuul spans have been improperly closed and the span remained in the main thread. After sending enough requests the traces started to be reused by the worker threads. fixes #634 --- .../sleuth/instrument/web/TraceFilter.java | 9 +- .../instrument/zuul/TracePreZuulFilter.java | 11 ++ .../web/multiple/DemoApplication.java | 6 +- .../zuul/issues/issue634/Issue634Tests.java | 106 ++++++++++++++++++ 4 files changed, 130 insertions(+), 2 deletions(-) create mode 100644 spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/issues/issue634/Issue634Tests.java 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 2b0657581..68486dcae 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 @@ -257,7 +257,8 @@ public class TraceFilter extends GenericFilterBean { log.debug("Closing the span " + span + " since the response was successful"); } tracer().close(span); - } else if (errorAlreadyHandled(request) && tracer().isTracing()) { + clearTraceAttribute(request); + } else if (errorAlreadyHandled(request) && tracer().isTracing() && !shouldCloseSpan(request)) { if (log.isDebugEnabled()) { log.debug( "Won't detach the span " + span + " since error has already been handled"); @@ -268,11 +269,13 @@ public class TraceFilter extends GenericFilterBean { "Will close span " + span + " since some component marked it for closure"); } tracer().close(span); + clearTraceAttribute(request); } else if (tracer().isTracing()) { if (log.isDebugEnabled()) { log.debug("Detaching the span " + span + " since the response was unsuccessful"); } tracer().detach(span); + clearTraceAttribute(request); } } } @@ -311,6 +314,10 @@ public class TraceFilter extends GenericFilterBean { return (Span) request.getAttribute(TRACE_REQUEST_ATTR); } + private void clearTraceAttribute(HttpServletRequest request) { + request.setAttribute(TRACE_REQUEST_ATTR, null); + } + private boolean errorAlreadyHandled(HttpServletRequest request) { return Boolean.valueOf( String.valueOf(request.getAttribute(TRACE_ERROR_HANDLED_REQUEST_ATTR))); diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePreZuulFilter.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePreZuulFilter.java index a5ba2d273..2416f2e4a 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePreZuulFilter.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/zuul/TracePreZuulFilter.java @@ -28,6 +28,7 @@ import org.springframework.cloud.sleuth.Span; import org.springframework.cloud.sleuth.Tracer; import org.springframework.cloud.sleuth.instrument.web.HttpSpanInjector; import org.springframework.cloud.sleuth.instrument.web.HttpTraceKeysInjector; +import org.springframework.cloud.sleuth.instrument.web.TraceFilter; import org.springframework.cloud.sleuth.instrument.web.TraceRequestAttributes; import java.lang.invoke.MethodHandles; @@ -44,6 +45,11 @@ public class TracePreZuulFilter extends ZuulFilter { private static final Log log = LogFactory.getLog(MethodHandles.lookup().lookupClass()); + private static final String TRACE_REQUEST_ATTR = TraceFilter.class.getName() + + ".TRACE"; + private static final String TRACE_CLOSE_SPAN_REQUEST_ATTR = TraceFilter.class.getName() + + ".CLOSE_SPAN"; + private static final String ZUUL_COMPONENT = "zuul"; private final Tracer tracer; @@ -94,6 +100,11 @@ public class TracePreZuulFilter extends ZuulFilter { if (log.isDebugEnabled()) { log.debug("New Zuul Span is " + newSpan + ""); } + if (log.isDebugEnabled()) { + log.debug("Setting attributes for TraceFilter to pick up later"); + } + RequestContext.getCurrentContext().getRequest().setAttribute(TRACE_REQUEST_ATTR, this.tracer.getCurrentSpan()); + RequestContext.getCurrentContext().getRequest().setAttribute(TRACE_CLOSE_SPAN_REQUEST_ATTR, true); ZuulFilterResult result = super.runFilter(); if (log.isDebugEnabled()) { log.debug("Result of Zuul filter is [" + result.getStatus() + "]"); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/multiple/DemoApplication.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/multiple/DemoApplication.java index b30b02c84..49334ecd8 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/multiple/DemoApplication.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/web/multiple/DemoApplication.java @@ -3,6 +3,8 @@ package org.springframework.cloud.sleuth.instrument.web.multiple; import java.util.Arrays; import java.util.List; +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.integration.annotation.Aggregator; import org.springframework.integration.annotation.Gateway; @@ -21,6 +23,8 @@ import org.springframework.web.bind.annotation.RestController; @IntegrationComponentScan public class DemoApplication { + private static final Log log = LogFactory.getLog(DemoApplication.class); + @Autowired Sender sender; @@ -42,7 +46,7 @@ public class DemoApplication { @ServiceActivator(inputChannel="counts") public void report(int count) { - System.err.println("Count: " + count); + log.info("Count: " + count); } } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/issues/issue634/Issue634Tests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/issues/issue634/Issue634Tests.java new file mode 100644 index 000000000..2f9d98873 --- /dev/null +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/zuul/issues/issue634/Issue634Tests.java @@ -0,0 +1,106 @@ +package org.springframework.cloud.sleuth.instrument.zuul.issues.issue634; + +import java.util.HashSet; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; + +import com.netflix.zuul.ZuulFilter; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.boot.autoconfigure.EnableAutoConfiguration; +import org.springframework.boot.context.embedded.LocalServerPort; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.boot.test.web.client.TestRestTemplate; +import org.springframework.cloud.netflix.zuul.EnableZuulProxy; +import org.springframework.cloud.sleuth.Tracer; +import org.springframework.cloud.sleuth.trace.TestSpanContextHolder; +import org.springframework.cloud.sleuth.util.ExceptionUtils; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.test.annotation.DirtiesContext; +import org.springframework.test.context.junit4.SpringRunner; + +import static org.assertj.core.api.BDDAssertions.then; + +@RunWith(SpringRunner.class) +@SpringBootTest(classes = TestZuulApplication.class, + webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT, + properties = {"feign.hystrix.enabled=false", + "zuul.routes.dp.path:/display/**", + "zuul.routes.dp.path.url: http://localhost:9987/unknown"}) +@DirtiesContext +public class Issue634Tests { + + @LocalServerPort int port; + @Autowired Tracer tracer; + @Autowired TraceCheckingSpanFilter filter; + + @Before + public void setup() { + TestSpanContextHolder.removeCurrentSpan(); + ExceptionUtils.setFail(true); + } + + @After + public void close() { + TestSpanContextHolder.removeCurrentSpan(); + } + + @Test + public void should_reuse_custom_feign_client() { + for (int i = 0; i < 15; i++) { + new TestRestTemplate() + .getForEntity("http://localhost:" + this.port + "/display/ddd", + String.class); + + then(this.tracer.getCurrentSpan()).isNull(); + then(ExceptionUtils.getLastException()).isNull(); + } + then(new HashSet<>(this.filter.counter.values())) + .describedAs("trace id should not be reused from thread").hasSize(1); + } +} + +@EnableZuulProxy +@EnableAutoConfiguration +@Configuration +class TestZuulApplication { + + @Bean + TraceCheckingSpanFilter traceCheckingSpanFilter(Tracer tracer) { + return new TraceCheckingSpanFilter(tracer); + } + +} + +class TraceCheckingSpanFilter extends ZuulFilter { + + private final Tracer tracer; + final Map counter = new ConcurrentHashMap<>(); + + TraceCheckingSpanFilter(Tracer tracer) { + this.tracer = tracer; + } + + @Override public String filterType() { + return "post"; + } + + @Override public int filterOrder() { + return -1; + } + + @Override public boolean shouldFilter() { + return true; + } + + @Override public Object run() { + long trace = this.tracer.getCurrentSpan().getTraceId(); + Integer integer = this.counter.getOrDefault(trace, 0); + counter.put(trace, integer + 1); + return null; + } +} \ No newline at end of file