Make sure span.finish() is not called twice

tests/integration/mp-gh-2461/pom.xml

@@ -0,0 +1,62 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<!--
+
+    Copyright (c) 2020 Oracle and/or its affiliates.
+
+    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.
+
+-->
+<project xmlns="http://maven.apache.org/POM/4.0.0"
+        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+        xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
+    <parent>
+        <artifactId>helidon-tests-integration</artifactId>
+        <groupId>io.helidon.tests.integration</groupId>
+        <version>2.1.1-SNAPSHOT</version>
+    </parent>
+    <modelVersion>4.0.0</modelVersion>
+
+    <artifactId>helidon-tests-integration-mp-gh-2461</artifactId>
+    <name>Helidon Tests Integration MP GH 2461</name>
+    <description>Reproducer for Github issue #2461 - attempt to use finished span</description>
+
+    <dependencies>
+        <dependency>
+            <groupId>io.helidon.microprofile.bundles</groupId>
+            <artifactId>helidon-microprofile-core</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>io.helidon.microprofile.tracing</groupId>
+            <artifactId>helidon-microprofile-tracing</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>io.helidon.tracing</groupId>
+            <artifactId>helidon-tracing-jaeger</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>org.junit.jupiter</groupId>
+            <artifactId>junit-jupiter-api</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.hamcrest</groupId>
+            <artifactId>hamcrest-all</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>io.helidon.microprofile.tests</groupId>
+            <artifactId>helidon-microprofile-tests-junit5</artifactId>
+            <scope>test</scope>
+        </dependency>
+    </dependencies>
+</project>

tests/integration/mp-gh-2461/src/test/java/io/helidon/tests/integration/gh2461/Gh2461Test.java

@@ -0,0 +1,195 @@
+/*
+ * Copyright (c) 2020 Oracle and/or its affiliates.
+ *
+ * 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 io.helidon.tests.integration.gh2461;
+
+import java.io.BufferedWriter;
+import java.io.OutputStreamWriter;
+import java.io.Writer;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.logging.Handler;
+import java.util.logging.Level;
+import java.util.logging.LogRecord;
+import java.util.logging.Logger;
+
+import javax.enterprise.context.RequestScoped;
+import javax.inject.Inject;
+import javax.ws.rs.GET;
+import javax.ws.rs.Path;
+import javax.ws.rs.QueryParam;
+import javax.ws.rs.WebApplicationException;
+import javax.ws.rs.client.WebTarget;
+import javax.ws.rs.core.Response;
+import javax.ws.rs.core.StreamingOutput;
+
+import io.helidon.microprofile.tests.junit5.AddBean;
+import io.helidon.microprofile.tests.junit5.HelidonTest;
+
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+
+import static org.hamcrest.CoreMatchers.is;
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.junit.jupiter.api.Assertions.assertThrows;
+
+@HelidonTest
+@AddBean(Gh2461Test.TestResource.class)
+class Gh2461Test {
+    private static final Logger FILTER_LOGGER = Logger.getLogger("io.helidon.tracing.jersey.AbstractTracingFilter");
+    private static final Logger JAEGER_LOGGER = Logger.getLogger("io.jaegertracing.internal.JaegerSpan");
+
+    private final TestHandler filterTestHandler = new TestHandler();
+    private final TestHandler jaegerTestHandler = new TestHandler();
+
+    @Inject
+    private WebTarget target;
+
+    @BeforeEach
+    void beforeEach() {
+        FILTER_LOGGER.addHandler(filterTestHandler);
+        JAEGER_LOGGER.addHandler(jaegerTestHandler);
+    }
+
+    @AfterEach
+    void afterEach() {
+        FILTER_LOGGER.removeHandler(filterTestHandler);
+        JAEGER_LOGGER.removeHandler(jaegerTestHandler);
+        filterTestHandler.reset();
+        jaegerTestHandler.reset();
+    }
+
+    @Test
+    void testTracing() {
+        String response = target.path("/test")
+                .request()
+                .get(String.class);
+
+        assertThat(response, is("Test Message"));
+
+        response = target.path("/test")
+                .request()
+                .get(String.class);
+
+        assertThat(response, is("Test Message"));
+
+        int count = 0;
+        for (LogRecord o : filterTestHandler.recordList) {
+            if (o.getLevel() == Level.WARNING) {
+                if (o.getMessage().contains("Response filter called twice.")) {
+                    count++;
+                }
+            }
+        }
+        assertThat("Normal processing should not include warnings", count, is(0));
+
+        // make sure
+        // 08:03:44.288 [helidon-1] WARN  io.jaegertracing.internal.JaegerSpan - Span has already been finished; will not be
+        //reported again.
+        // not logged at all
+        count = 0;
+        for (LogRecord o : jaegerTestHandler.recordList) {
+            if (o.getMessage().contains("Span has already been finished; will not be reported again.")) {
+                count++;
+            }
+        }
+        assertThat("Jaeger span should never be called twice.", count, is(0));
+    }
+
+    @Test
+    void failTracing() {
+        assertThrows(WebApplicationException.class, () -> target.path("/test")
+                .queryParam("throwError", true)
+                .request()
+                .get(String.class));
+
+        assertThrows(WebApplicationException.class, () -> target.path("/test")
+                .queryParam("throwError", true)
+                .request()
+                .get(String.class));
+
+        // make sure
+        // 2020.10.18 21:25:53 WARNING io.helidon.tracing.jersey.AbstractTracingFilter filter io.helidon.tracing.jersey
+        //.AbstractTracingFilter Thread[helidon-3,5,server]: Response filter called twice. Most likely a response with
+        //streaming output was returned, where response had 200 status code, but streaming failed with another error. Status:
+        //Too Many Requests
+        // logged only once
+
+        int count = 0;
+        for (LogRecord o : filterTestHandler.recordList) {
+            if (o.getLevel() == Level.WARNING) {
+                if (o.getMessage().contains("Response filter called twice.")) {
+                    count++;
+                }
+            }
+        }
+        assertThat("Exactly one warning should be logged when filter is called twice", count, is(1));
+
+        // make sure
+        // 08:03:44.288 [helidon-1] WARN  io.jaegertracing.internal.JaegerSpan - Span has already been finished; will not be
+        //reported again.
+        // not logged at all
+        count = 0;
+        for (LogRecord o : jaegerTestHandler.recordList) {
+            if (o.getMessage().contains("Span has already been finished; will not be reported again.")) {
+                count++;
+            }
+        }
+        assertThat("Jaeger span should never be called twice.", count, is(0));
+    }
+
+    @Path("/test")
+    @RequestScoped
+    public static class TestResource {
+        @GET
+        public Response getTest(@QueryParam("throwError") final boolean throwError) {
+            StreamingOutput output = outputStream -> {
+                if (throwError) {
+                    throw new WebApplicationException("Capacity Exceeded.", 429);
+                }
+                Writer writer = new BufferedWriter(new OutputStreamWriter(outputStream));
+                writer.write("Test Message");
+                writer.flush();
+            };
+            return Response.ok().entity(output).build();
+        }
+    }
+
+    private static class TestHandler extends Handler {
+
+        List<LogRecord> recordList = new ArrayList<>();
+
+        void reset() {
+            recordList.clear();
+        }
+
+        @Override
+        public void publish(final LogRecord record) {
+            recordList.add(record);
+        }
+
+        @Override
+        public void flush() {
+
+        }
+
+        @Override
+        public void close() throws SecurityException {
+            reset();
+        }
+    }
+}

tests/integration/pom.xml

@@ -42,6 +42,7 @@
         <module>security</module>
         <module>mp-gh-1538</module>
         <module>mp-gh-2421</module>
+        <module>mp-gh-2461</module>
         <module>kafka</module>
     </modules>
 

tracing/jersey/src/main/java/io/helidon/tracing/jersey/AbstractTracingFilter.java

@@ -17,6 +17,8 @@
 
 import java.net.URI;
 import java.util.Map;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.logging.Logger;
 
 import javax.ws.rs.ConstrainedTo;
 import javax.ws.rs.RuntimeType;
@@ -47,9 +49,11 @@
 @ConstrainedTo(RuntimeType.SERVER)
 @PreMatching
 public abstract class AbstractTracingFilter implements ContainerRequestFilter, ContainerResponseFilter {
-
     private static final String SPAN_PROPERTY = AbstractTracingFilter.class.getName() + ".span";
     private static final String SPAN_SCOPE_PROPERTY = AbstractTracingFilter.class.getName() + ".spanScope";
+    private static final String SPAN_FINISHED_PROPERTY = AbstractTracingFilter.class.getName() + ".spanFinished";
+    private static final Logger LOGGER = Logger.getLogger(AbstractTracingFilter.class.getName());
+    private static final AtomicBoolean DOUBLE_FINISH_LOGGED = new AtomicBoolean();
 
     @Override
     public void filter(ContainerRequestContext requestContext) {
@@ -130,6 +134,16 @@ public void filter(ContainerRequestContext requestContext, ContainerResponseCont
             return; // not tracing
         }
 
+        if (requestContext.getProperty(SPAN_FINISHED_PROPERTY) != null) {
+            if (DOUBLE_FINISH_LOGGED.compareAndSet(false, true)) {
+                LOGGER.warning("Response filter called twice. Most likely a response with streaming output was"
+                                       + " returned, where response had 200 status code, but streaming failed with another "
+                                       + "error. Status: " + responseContext.getStatusInfo());
+            }
+
+            return; // tracing already finished
+        }
+
         switch (responseContext.getStatusInfo().getFamily()) {
         case INFORMATIONAL:
         case SUCCESSFUL:
@@ -148,6 +162,7 @@ public void filter(ContainerRequestContext requestContext, ContainerResponseCont
 
         Tags.HTTP_STATUS.set(span, responseContext.getStatus());
 
+        requestContext.setProperty(SPAN_FINISHED_PROPERTY, true);
         span.finish();
 
         Scope spanScope = (Scope) requestContext.getProperty(SPAN_SCOPE_PROPERTY);