[cxf] branch master updated: CXF-8169: Span#finish is never called in case of client timeouts

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

[cxf] branch master updated: CXF-8169: Span#finish is never called in case of client timeouts

reta
This is an automated email from the ASF dual-hosted git repository.

reta pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/cxf.git


The following commit(s) were added to refs/heads/master by this push:
     new 7b50181  CXF-8169: Span#finish is never called in case of client timeouts
7b50181 is described below

commit 7b50181ebc445bb84d3463b284643432399bc0f8
Author: reta <[hidden email]>
AuthorDate: Sun Dec 1 17:16:38 2019 -0500

    CXF-8169: Span#finish is never called in case of client timeouts
---
 .../tracing/brave/AbstractBraveClientProvider.java | 22 +++++++++++++
 .../tracing/brave/BraveClientStartInterceptor.java | 10 ++++++
 .../AbstractOpenTracingClientProvider.java         | 30 +++++++++++++++++
 .../OpenTracingClientStartInterceptor.java         | 11 ++++++-
 .../cxf/systest/jaxrs/tracing/BookStore.java       |  8 +++++
 .../jaxrs/tracing/brave/BraveTracingTest.java      | 34 +++++++++++++++++++
 .../jaxrs/tracing/opentracing/IsTagContaining.java |  4 +--
 .../opentracing/OpenTracingTracingTest.java        | 38 ++++++++++++++++++++--
 8 files changed, 152 insertions(+), 5 deletions(-)

diff --git a/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/AbstractBraveClientProvider.java b/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/AbstractBraveClientProvider.java
index 4c4c5e2..2f4d7ed 100644
--- a/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/AbstractBraveClientProvider.java
+++ b/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/AbstractBraveClientProvider.java
@@ -108,4 +108,26 @@ public abstract class AbstractBraveClientProvider extends AbstractTracingProvide
             }
         }
     }
+    
+    protected void stopTraceSpan(final TraceScopeHolder<TraceScope> holder, final Throwable ex) {
+        if (holder == null) {
+            return;
+        }
+
+        final TraceScope scope = holder.getScope();
+        if (scope != null) {
+            try {
+                // If the client invocation was asynchronous , the trace span has been created
+                // in another thread and should be re-attached to the current one.
+                if (holder.isDetached()) {
+                    brave.tracing().tracer().joinSpan(scope.getSpan().context());
+                }
+    
+                final HttpClientHandler<?, Response> handler = HttpClientHandler.create(brave, null);
+                handler.handleReceive(null, ex, scope.getSpan());
+            } finally {
+                scope.close();
+            }
+        }
+    }
 }
diff --git a/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/BraveClientStartInterceptor.java b/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/BraveClientStartInterceptor.java
index 2916c41..d33c4ad 100644
--- a/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/BraveClientStartInterceptor.java
+++ b/integration/tracing/tracing-brave/src/main/java/org/apache/cxf/tracing/brave/BraveClientStartInterceptor.java
@@ -44,4 +44,14 @@ public class BraveClientStartInterceptor extends AbstractBraveClientInterceptor
             message.getExchange().put(TRACE_SPAN, holder);
         }
     }
+    
+    @Override
+    public void handleFault(Message message) {
+        @SuppressWarnings("unchecked")
+        final TraceScopeHolder<TraceScope> holder =
+            (TraceScopeHolder<TraceScope>)message.getExchange().get(TRACE_SPAN);
+        
+        final Exception ex = message.getContent(Exception.class);
+        super.stopTraceSpan(holder, ex);
+    }
 }
diff --git a/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/AbstractOpenTracingClientProvider.java b/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/AbstractOpenTracingClientProvider.java
index ef9a526..2da43c5 100644
--- a/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/AbstractOpenTracingClientProvider.java
+++ b/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/AbstractOpenTracingClientProvider.java
@@ -19,6 +19,7 @@
 package org.apache.cxf.tracing.opentracing;
 
 import java.net.URI;
+import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
 import java.util.logging.Logger;
@@ -103,4 +104,33 @@ public abstract class AbstractOpenTracingClientProvider extends AbstractTracingP
             scope.close();
         }
     }
+    
+    protected void stopTraceSpan(final TraceScopeHolder<TraceScope> holder, final Throwable ex) {
+        if (holder == null) {
+            return;
+        }
+
+        final TraceScope traceScope = holder.getScope();
+        if (traceScope != null) {
+            Span span = traceScope.getSpan();
+            Scope scope = traceScope.getScope();
+            
+            // If the client invocation was asynchronous , the trace span has been created
+            // in another thread and should be re-attached to the current one.
+            if (holder.isDetached()) {
+                scope = tracer.scopeManager().activate(span);
+            }
+
+            span.setTag(Tags.ERROR.getKey(), Boolean.TRUE);
+            if (ex != null) {
+                final Map<String, Object> logEvent = new HashMap<>(2);
+                logEvent.put("event", Tags.ERROR.getKey());
+                logEvent.put("message", ex.getMessage());
+                span.log(logEvent);
+            }
+            span.finish();
+            
+            scope.close();
+        }
+    }
 }
diff --git a/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/OpenTracingClientStartInterceptor.java b/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/OpenTracingClientStartInterceptor.java
index 011fef6..578fe49 100644
--- a/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/OpenTracingClientStartInterceptor.java
+++ b/integration/tracing/tracing-opentracing/src/main/java/org/apache/cxf/tracing/opentracing/OpenTracingClientStartInterceptor.java
@@ -47,5 +47,14 @@ public class OpenTracingClientStartInterceptor extends AbstractOpenTracingClient
             message.getExchange().put(TRACE_SPAN, holder);
         }
     }
-
+    
+    @Override
+    public void handleFault(Message message) {
+        @SuppressWarnings("unchecked")
+        final TraceScopeHolder<TraceScope> holder =
+            (TraceScopeHolder<TraceScope>)message.getExchange().get(TRACE_SPAN);
+        
+        final Exception ex = message.getContent(Exception.class);
+        super.stopTraceSpan(holder, ex);
+    }
 }
diff --git a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/BookStore.java b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/BookStore.java
index f460540..1f6d752 100644
--- a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/BookStore.java
+++ b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/BookStore.java
@@ -124,6 +124,14 @@ public class BookStore<T extends Closeable> {
         return Response.ok().build();
     }
 
+    @GET
+    @Path("/books/long")
+    @Produces(MediaType.APPLICATION_JSON)
+    public Collection<Book> getBooksLong() throws InterruptedException {
+        Thread.sleep(500);
+        return books();
+    }
+    
     private static Collection<Book> books() {
         return Arrays.asList(
                 new Book("Apache CXF in Action", UUID.randomUUID().toString()),
diff --git a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/brave/BraveTracingTest.java b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/brave/BraveTracingTest.java
index a5cbadb..08e99ae 100644
--- a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/brave/BraveTracingTest.java
+++ b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/brave/BraveTracingTest.java
@@ -20,6 +20,7 @@ package org.apache.cxf.systest.jaxrs.tracing.brave;
 
 import java.net.MalformedURLException;
 import java.util.Arrays;
+import java.util.Collections;
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
@@ -27,6 +28,7 @@ import java.util.concurrent.TimeoutException;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.stream.IntStream;
 
+import javax.ws.rs.ProcessingException;
 import javax.ws.rs.core.MediaType;
 import javax.ws.rs.core.Response;
 import javax.ws.rs.core.Response.Status;
@@ -46,14 +48,18 @@ import org.apache.cxf.systest.brave.TestSpanReporter;
 import org.apache.cxf.systest.jaxrs.tracing.BookStore;
 import org.apache.cxf.testutil.common.AbstractClientServerTestBase;
 import org.apache.cxf.testutil.common.AbstractTestServerBase;
+import org.apache.cxf.tracing.brave.BraveClientFeature;
 import org.apache.cxf.tracing.brave.TraceScope;
 import org.apache.cxf.tracing.brave.jaxrs.BraveClientProvider;
 import org.apache.cxf.tracing.brave.jaxrs.BraveFeature;
+import org.apache.cxf.transports.http.configuration.HTTPClientPolicy;
 import org.awaitility.Duration;
 
 import org.junit.After;
 import org.junit.BeforeClass;
+import org.junit.Rule;
 import org.junit.Test;
+import org.junit.rules.ExpectedException;
 
 import static org.apache.cxf.systest.brave.BraveTestSupport.PARENT_SPAN_ID_NAME;
 import static org.apache.cxf.systest.brave.BraveTestSupport.SAMPLED_NAME;
@@ -67,6 +73,7 @@ import static org.hamcrest.CoreMatchers.not;
 import static org.hamcrest.CoreMatchers.nullValue;
 import static org.hamcrest.MatcherAssert.assertThat;
 import static org.hamcrest.collection.IsMapContaining.hasEntry;
+import static org.hamcrest.collection.IsMapContaining.hasKey;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertTrue;
@@ -76,6 +83,9 @@ public class BraveTracingTest extends AbstractClientServerTestBase {
 
     private static final AtomicLong RANDOM = new AtomicLong();
 
+    @Rule
+    public ExpectedException expectedException = ExpectedException.none();
+
     private final Tracing brave = Tracing.newBuilder()
         .spanReporter(new TestSpanReporter())
         .build();
@@ -387,6 +397,30 @@ public class BraveTracingTest extends AbstractClientServerTestBase {
         assertThatTraceHeadersArePresent(r, false);
     }
 
+    @Test
+    public void testThatNewSpanIsCreatedOnClientTimeout() {
+        final WebClient client = WebClient
+            .create("http://localhost:" + PORT + "/bookstore/books/long", Collections.emptyList(),
+                Arrays.asList(new BraveClientFeature(brave)), null)
+            .accept(MediaType.APPLICATION_JSON);
+        
+        HTTPClientPolicy httpClientPolicy = new HTTPClientPolicy();
+        httpClientPolicy.setConnectionTimeout(100);
+        httpClientPolicy.setReceiveTimeout(100);
+        WebClient.getConfig(client).getHttpConduit().setClient(httpClientPolicy);
+
+        expectedException.expect(ProcessingException.class);
+        try {
+            client.get();
+        } finally {
+            await().atMost(Duration.ONE_SECOND).until(()-> TestSpanReporter.getAllSpans().size() == 2);
+            assertThat(TestSpanReporter.getAllSpans().size(), equalTo(2));
+            assertThat(TestSpanReporter.getAllSpans().get(0).name(), equalTo("get " + client.getCurrentURI()));
+            assertThat(TestSpanReporter.getAllSpans().get(0).tags(), hasKey("error"));
+            assertThat(TestSpanReporter.getAllSpans().get(1).name(), equalTo("get /bookstore/books/long"));
+        }
+    }
+
     private static WebClient createWebClient(final String path, final Object ... providers) {
         return WebClient
             .create("http://localhost:" + PORT + path, Arrays.asList(providers))
diff --git a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/IsTagContaining.java b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/IsTagContaining.java
index b9ac95a..8cad059 100644
--- a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/IsTagContaining.java
+++ b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/IsTagContaining.java
@@ -23,11 +23,11 @@ import org.hamcrest.collection.IsMapContaining;
 import static org.hamcrest.CoreMatchers.equalTo;
 
 public class IsTagContaining extends IsMapContaining<String, Object> {
-    public IsTagContaining(final String key, final String value) {
+    public IsTagContaining(final String key, final Object value) {
         super(equalTo(key), equalTo(value));
     }
 
-    public static IsTagContaining hasItem(final String key, final String value) {
+    public static IsTagContaining hasItem(final String key, final Object value) {
         return new IsTagContaining(key, value);
     }
 }
\ No newline at end of file
diff --git a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/OpenTracingTracingTest.java b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/OpenTracingTracingTest.java
index 513ccf7..058b05c 100644
--- a/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/OpenTracingTracingTest.java
+++ b/systests/tracing/src/test/java/org/apache/cxf/systest/jaxrs/tracing/opentracing/OpenTracingTracingTest.java
@@ -20,6 +20,7 @@ package org.apache.cxf.systest.jaxrs.tracing.opentracing;
 
 import java.net.MalformedURLException;
 import java.util.Arrays;
+import java.util.Collections;
 import java.util.Iterator;
 import java.util.Map.Entry;
 import java.util.concurrent.ExecutionException;
@@ -29,6 +30,7 @@ import java.util.concurrent.TimeoutException;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.stream.IntStream;
 
+import javax.ws.rs.ProcessingException;
 import javax.ws.rs.core.MediaType;
 import javax.ws.rs.core.Response;
 import javax.ws.rs.core.Response.Status;
@@ -42,8 +44,10 @@ import org.apache.cxf.jaxrs.model.AbstractResourceInfo;
 import org.apache.cxf.systest.jaxrs.tracing.BookStore;
 import org.apache.cxf.testutil.common.AbstractClientServerTestBase;
 import org.apache.cxf.testutil.common.AbstractTestServerBase;
+import org.apache.cxf.tracing.opentracing.OpenTracingClientFeature;
 import org.apache.cxf.tracing.opentracing.jaxrs.OpenTracingClientProvider;
 import org.apache.cxf.tracing.opentracing.jaxrs.OpenTracingFeature;
+import org.apache.cxf.transports.http.configuration.HTTPClientPolicy;
 import org.awaitility.Duration;
 
 import io.jaegertracing.internal.JaegerSpanContext;
@@ -55,10 +59,13 @@ import io.opentracing.Span;
 import io.opentracing.Tracer;
 import io.opentracing.propagation.Format.Builtin;
 import io.opentracing.propagation.TextMap;
+import io.opentracing.tag.Tags;
 
 import org.junit.After;
 import org.junit.BeforeClass;
+import org.junit.Rule;
 import org.junit.Test;
+import org.junit.rules.ExpectedException;
 
 import static org.apache.cxf.systest.jaxrs.tracing.opentracing.HasSpan.hasSpan;
 import static org.apache.cxf.systest.jaxrs.tracing.opentracing.IsLogContaining.hasItem;
@@ -78,11 +85,14 @@ public class OpenTracingTracingTest extends AbstractClientServerTestBase {
 
     private static final InMemoryReporter REPORTER = new InMemoryReporter();
 
+    @Rule
+    public ExpectedException expectedException = ExpectedException.none();
+
     private final Tracer tracer = new JaegerTracer.Builder("tracer-jaxrs")
         .withSampler(new ConstSampler(true))
         .withReporter(REPORTER)
         .build();
-
+    
     public static class BraveServer extends AbstractTestServerBase {
 
         private org.apache.cxf.endpoint.Server server;
@@ -108,7 +118,7 @@ public class OpenTracingTracingTest extends AbstractClientServerTestBase {
             server.destroy();
         }
     }
-
+    
     @BeforeClass
     public static void startServers() throws Exception {
         AbstractResourceInfo.clearAllMaps();
@@ -356,6 +366,30 @@ public class OpenTracingTracingTest extends AbstractClientServerTestBase {
         assertThat(REPORTER.getSpans().get(0).getOperationName(), equalTo("Processing books"));
     }
 
+    @Test
+    public void testThatNewSpanIsCreatedOnClientTimeout() {
+        final WebClient client = WebClient
+            .create("http://localhost:" + PORT + "/bookstore/books/long", Collections.emptyList(),
+                Arrays.asList(new OpenTracingClientFeature(tracer)), null)
+            .accept(MediaType.APPLICATION_JSON);
+        
+        HTTPClientPolicy httpClientPolicy = new HTTPClientPolicy();
+        httpClientPolicy.setConnectionTimeout(100);
+        httpClientPolicy.setReceiveTimeout(100);
+        WebClient.getConfig(client).getHttpConduit().setClient(httpClientPolicy);
+
+        expectedException.expect(ProcessingException.class);
+        try {
+            client.get();
+        } finally {
+            await().atMost(Duration.ONE_SECOND).until(()-> REPORTER.getSpans().size() == 2);
+            assertThat(REPORTER.getSpans().toString(), REPORTER.getSpans().size(), equalTo(2));
+            assertThat(REPORTER.getSpans().get(0).getOperationName(), equalTo("GET " + client.getCurrentURI()));
+            assertThat(REPORTER.getSpans().get(0).getTags(), hasItem(Tags.ERROR.getKey(), Boolean.TRUE));
+            assertThat(REPORTER.getSpans().get(1).getOperationName(), equalTo("GET /bookstore/books/long"));
+        }
+    }
+    
     private static WebClient createWebClient(final String path, final Object ... providers) {
         return WebClient
             .create("http://localhost:" + PORT + path, Arrays.asList(providers))