Makes all instrumentation call Span.finish in scope

See #999 (comment)

instrumentation/RATIONALE.md

@@ -0,0 +1,36 @@
+# brave-instrumentation rationale
+
+## Calling `Span.finish()` while the context is in scope
+Instrumentation should call `Span.finish()` with the same context in scope as
+opposed to clearing or using a different span context.
+
+It may seem that clearing it is a better choice, but that actually causes
+overhead as there are often decorators attached, which do things like log
+property synchronization.
+
+It may also seem that this could lead to accidental tracing to Zipkin itself.
+This is possible. If a library that itself is instrumented with Brave is used
+as a `Sender`, the application trace could continue into Zipkin. However, this
+is also possible even if the context was reset to null. A traced client
+encountering a cleared context would start a new trace, subject to its sampling
+policy.
+
+The only thing that resetting to cleared context would do vs not clearing is
+about continuation. If the context isn't cleared, the application trace would
+continue into Zipkin: any spans about span collection and storage will attach
+to the application trace. Note that this would only occur if the server is set
+to `SELF_TRACING_ENABLED=true` as tracing isn't enabled any other way.
+
+`SELF_TRACING_ENABLED` isn't a usual configuration, and trace continuation can
+be easily prevented by client configuration. For example, no packaged sender in
+`zipkin-reporter` inherits tracing configuration. Moreover, all recommended
+patterns of span reporting involve `AsyncReporter`, which already breaks traces
+with its internal thread. In other words, accidentally passing trace headers is
+only a risk in 3rd party reporters. These third parties can easily avoid the
+concern by clearing headers from `Propagation.keys()` or using raw, untraced
+clients.
+
+In summary, we don't clear trace context to save overhead, and accept a small
+risk of confusion where application traces have Zipkin spans in them when the
+server has `SELF_TRACING_ENABLED=true` and a 3rd party traced reporter is in
+use.

instrumentation/dubbo-rpc/src/main/java/brave/dubbo/rpc/TracingFilter.java

@@ -117,22 +117,26 @@ public void setRpcTracing(RpcTracing rpcTracing) {
     }
 
     boolean isOneway = false, deferFinish = false;
-    try (CurrentTraceContext.Scope scope = current.newScope(span.context())) {
+    CurrentTraceContext.Scope scope = current.newScope(span.context());
+    Throwable error = null;
+    try {
       Result result = invoker.invoke(invocation);
       isOneway = RpcUtils.isOneway(invoker.getUrl(), invocation);
       if (!span.isNoop()) {
         deferFinish = ensureSpanFinishes(rpcContext, span, result);
       }
       return result;
     } catch (Error | RuntimeException e) {
-      onError(e, span);
+      error = e;
       throw e;
     } finally {
+      if (error != null) onError(error, span);
       if (isOneway) {
         span.flush();
       } else if (!deferFinish) {
         span.finish();
       }
+      scope.close();
     }
   }
 

instrumentation/dubbo/src/main/java/brave/dubbo/TracingFilter.java

@@ -114,7 +114,9 @@ public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcExcept
     }
 
     boolean isOneway = false, deferFinish = false;
-    try (Tracer.SpanInScope scope = tracer.withSpanInScope(span)) {
+    Tracer.SpanInScope scope = tracer.withSpanInScope(span);
+    Throwable error = null;
+    try {
       Result result = invoker.invoke(invocation);
       if (result.hasException()) {
         onError(result.getException(), span);
@@ -134,14 +136,16 @@ public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcExcept
       }
       return result;
     } catch (Error | RuntimeException e) {
-      onError(e, span);
+      error = e;
       throw e;
     } finally {
+      if (error != null) onError(error, span);
       if (isOneway) {
         span.flush();
       } else if (!deferFinish) {
         span.finish();
       }
+      scope.close();
     }
   }
 

instrumentation/grpc/src/main/java/brave/grpc/TracingClientInterceptor.java

@@ -58,6 +58,7 @@ public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(MethodDescriptor<ReqT
     Span span = tracer.nextSpan(sampler, request);
 
     SpanInScope scope = tracer.withSpanInScope(span);
+    Throwable error = null;
     try {
       return new SimpleForwardingClientCall<ReqT, RespT>(next.newCall(method, callOptions)) {
         @Override public void start(Listener<RespT> responseListener, Metadata headers) {
@@ -84,9 +85,10 @@ public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(MethodDescriptor<ReqT
         }
       };
     } catch (RuntimeException | Error e) {
-      span.error(e).finish();
+      error = e;
       throw e;
     } finally {
+      if (error != null) span.error(error).finish();
       scope.close();
     }
   }
@@ -115,8 +117,8 @@ final class TracingClientCallListener<RespT> extends SimpleForwardingClientCallL
         super.onClose(status, trailers);
         parser.onClose(status, trailers, span.customizer());
       } finally {
-        scope.close();
         span.finish();
+        scope.close();
       }
     }
   }

instrumentation/grpc/src/main/java/brave/grpc/TracingServerInterceptor.java

@@ -66,13 +66,14 @@ public <ReqT, RespT> ServerCall.Listener<ReqT> interceptCall(ServerCall<ReqT, Re
     // startCall invokes user interceptors, so we place the span in scope here
     ServerCall.Listener<ReqT> result;
     SpanInScope scope = tracer.withSpanInScope(span);
-    try { // retrolambda can't resolve this try/finally
+    Throwable error = null;
+    try {
       result = next.startCall(new TracingServerCall<>(span, call), headers);
     } catch (RuntimeException | Error e) {
-      span.error(e);
-      span.finish();
+      error = e;
       throw e;
     } finally {
+      if (error != null) span.error(error).finish();
       scope.close();
     }
 
@@ -94,6 +95,7 @@ Span nextSpan(TraceContextOrSamplingFlags extracted, GrpcServerRequest request)
       : tracer.nextSpan(extracted);
   }
 
+  // TODO: this looks like it should be scoping, but isn't. Revisit
   final class TracingServerCall<ReqT, RespT> extends SimpleForwardingServerCall<ReqT, RespT> {
     final Span span;
 
@@ -152,15 +154,16 @@ static final class ScopingServerCallListener<ReqT>
 
     @Override public void onHalfClose() {
       SpanInScope scope = tracer.withSpanInScope(span);
-      try { // retrolambda can't resolve this try/finally
+      Throwable error = null;
+      try {
         delegate().onHalfClose();
       } catch (RuntimeException | Error e) {
-        // If there was an exception executing onHalfClose, we don't expect other lifecycle
-        // commands to succeed. Accordingly, we close the span
-        span.error(e);
-        span.finish();
+        error = e;
         throw e;
       } finally {
+        // If there was an exception executing onHalfClose, we don't expect other lifecycle
+        // commands to succeed. Accordingly, we close the span
+        if (error != null) span.error(error).finish();
         scope.close();
       }
     }

instrumentation/http-tests/src/main/java/brave/test/http/ITHttp.java

@@ -21,7 +21,6 @@
 import brave.propagation.ExtraFieldPropagation;
 import brave.propagation.StrictScopeDecorator;
 import brave.propagation.ThreadLocalCurrentTraceContext;
-import brave.propagation.TraceContext;
 import brave.sampler.Sampler;
 import java.util.concurrent.BlockingQueue;
 import java.util.concurrent.LinkedBlockingQueue;
@@ -31,7 +30,6 @@
 import org.junit.rules.TestRule;
 import org.junit.rules.TestWatcher;
 import org.junit.runner.Description;
-import zipkin2.Annotation;
 import zipkin2.Span;
 
 import static org.assertj.core.api.Assertions.assertThat;
@@ -94,7 +92,6 @@
  */
 public abstract class ITHttp {
   public static final String EXTRA_KEY = "user-id";
-  static final String CONTEXT_LEAK = "context.leak";
 
   /**
    * When testing servers or asynchronous clients, spans are reported on a worker thread. In order
@@ -109,9 +106,6 @@ protected Span takeSpan() throws InterruptedException {
     assertThat(result)
       .withFailMessage("Span was not reported")
       .isNotNull();
-    assertThat(result.annotations())
-      .extracting(Annotation::value)
-      .doesNotContain(CONTEXT_LEAK);
     return result;
   }
 
@@ -154,23 +148,7 @@ protected Tracer tracer() {
 
   protected Tracing.Builder tracingBuilder(Sampler sampler) {
     return Tracing.newBuilder()
-      .spanReporter(s -> {
-        // make sure the context was cleared prior to finish.. no leaks!
-        TraceContext current = httpTracing.tracing().currentTraceContext().get();
-        boolean contextLeak = false;
-        if (current != null) {
-          // add annotation in addition to throwing, in case we are off the main thread
-          if (current.spanIdString().equals(s.id())) {
-            s = s.toBuilder().addAnnotation(s.timestampAsLong(), CONTEXT_LEAK).build();
-            contextLeak = true;
-          }
-        }
-        spans.add(s);
-        // throw so that we can see the path to the code that leaked the context
-        if (contextLeak) {
-          throw new AssertionError(CONTEXT_LEAK + " on " + Thread.currentThread().getName());
-        }
-      })
+      .spanReporter(spans::add)
       .propagationFactory(ExtraFieldPropagation.newFactory(B3Propagation.FACTORY, EXTRA_KEY))
       .currentTraceContext(currentTraceContext)
       .sampler(sampler);

instrumentation/http/README.md

@@ -164,13 +164,15 @@ You generally need to...
 ```java
 Span span = handler.handleSend(injector, request); // 1.
 Throwable error = null;
-try (Tracer.SpanInScope ws = tracer.withSpanInScope(span)) { // 2.
+SpanInScope scope = tracer.withSpanInScope(span); // 2.
+try {
   response = invoke(request); // 3.
 } catch (RuntimeException | Error e) {
   error = e; // 4.
   throw e;
 } finally {
   handler.handleReceive(response, error, span); // 5.
+  scope.close();
 }
 ```
 
@@ -204,13 +206,15 @@ You generally need to...
 ```java
 Span span = handler.handleReceive(extractor, request); // 1.
 Throwable error = null;
-try (Tracer.SpanInScope ws = tracer.withSpanInScope(span)) { // 2.
+SpanInScope scope = tracer.withSpanInScope(span); // 2.
+try { // 2.
   response = invoke(request); // 3.
 } catch (RuntimeException | Error e) {
   error = e; // 4.
   throw e;
 } finally {
   handler.handleSend(response, error, span); // 5.
+  scope.close();
 }
 ```
 

instrumentation/http/src/main/java/brave/http/HttpHandler.java

@@ -53,28 +53,19 @@ <Resp> void handleFinish(HttpAdapter<?, Resp> adapter, @Nullable Resp response,
     @Nullable Throwable error, Span span) {
     if (span.isNoop()) return;
     long finishTimestamp = response != null ? adapter.finishTimestamp(response) : 0L;
-    try {
-      Scope ws = currentTraceContext.maybeScope(span.context());
-      try {
-        parser.response(adapter, response, error, span.customizer());
-      } finally {
-        ws.close(); // close the scope before finishing the span
-      }
-    } finally {
-      finishInNullScope(span, finishTimestamp);
-    }
-  }
 
-  /** Clears the scope to prevent remote reporters from accidentally tracing */
-  void finishInNullScope(Span span, long timestamp) {
-    Scope ws = currentTraceContext.maybeScope(null);
+    // Scope the trace context so that log statements are valid and also parse code can use
+    // Tracer.currentSpan() as necessary.
+    Scope ws = currentTraceContext.maybeScope(span.context());
     try {
-      if (timestamp == 0L) {
+      parser.response(adapter, response, error, span.customizer());
+    } finally {
+      // See instrumentation/RATIONALE.md for why we call finish in scope
+      if (finishTimestamp == 0L) {
         span.finish();
       } else {
-        span.finish(timestamp);
+        span.finish(finishTimestamp);
       }
-    } finally {
       ws.close();
     }
   }

instrumentation/http/src/test/java/brave/http/HttpHandlerTest.java

@@ -36,6 +36,7 @@
 public class HttpHandlerTest {
   CurrentTraceContext currentTraceContext = ThreadLocalCurrentTraceContext.create();
   TraceContext context = TraceContext.newBuilder().traceId(1L).spanId(10L).build();
+  TraceContext context2 = TraceContext.newBuilder().traceId(1L).spanId(11L).build();
   @Mock HttpAdapter<Object, Object> adapter;
   @Mock brave.Span span;
   @Mock SpanCustomizer spanCustomizer;
@@ -122,18 +123,18 @@ public class HttpHandlerTest {
     handler.handleFinish(adapter, response, null, span);
   }
 
-  @Test public void handleFinish_finishesWhenSpanNotInScope() {
+  @Test public void handleFinish_finishesWithSpanInScope() {
     doAnswer(invocation -> {
-      assertThat(currentTraceContext.get()).isNull();
+      assertThat(currentTraceContext.get()).isEqualTo(span.context());
       return null;
     }).when(span).finish();
 
     handler.handleFinish(adapter, response, null, span);
   }
 
-  @Test public void handleFinish_finishesWhenSpanNotInScope_clearingIfNecessary() {
-    try (CurrentTraceContext.Scope ws = currentTraceContext.newScope(context)) {
-      handleFinish_finishesWhenSpanNotInScope();
+  @Test public void handleFinish_finishesWithSpanInScope_resettingIfNecessary() {
+    try (CurrentTraceContext.Scope ws = currentTraceContext.newScope(context2)) {
+      handleFinish_finishesWithSpanInScope();
     }
   }
 

instrumentation/jersey-server/src/main/java/brave/jersey/server/TracingApplicationEventListener.java

@@ -100,16 +100,16 @@ public void onEvent(RequestEvent event) {
           spanInScope = tracer.withSpanInScope(span);
           break;
         case FINISHED:
-          // In async FINISHED can happen before RESOURCE_METHOD_FINISHED, and on different threads!
-          // Don't close the scope unless it is a synchronous method.
-          if (!async && (maybeSpanInScope = spanInScope) != null) {
-            maybeSpanInScope.close();
-          }
           String maybeHttpRoute = route(event.getContainerRequest());
           if (maybeHttpRoute != null) {
             event.getContainerRequest().setProperty("http.route", maybeHttpRoute);
           }
           handler.handleSend(new HttpServerResponse(event), event.getException(), span);
+          // In async FINISHED can happen before RESOURCE_METHOD_FINISHED, and on different threads!
+          // Don't close the scope unless it is a synchronous method.
+          if (!async && (maybeSpanInScope = spanInScope) != null) {
+            maybeSpanInScope.close();
+          }
           break;
         default:
       }

instrumentation/jms/src/main/java/brave/jms/TracingCompletionListener.java

@@ -40,19 +40,23 @@ static CompletionListener create(CompletionListener delegate, Span span,
   }
 
   @Override public void onCompletion(Message message) {
-    try (Scope ws = current.maybeScope(span.context())) {
+    Scope ws = current.maybeScope(span.context());
+    try {
       delegate.onCompletion(message);
     } finally {
       span.finish();
+      ws.close();
     }
   }
 
   @Override public void onException(Message message, Exception exception) {
-    try (Scope ws = current.maybeScope(span.context())) {
+    Scope ws = current.maybeScope(span.context());
+    try {
       delegate.onException(message, exception);
     } finally {
       span.error(exception);
       span.finish();
+      ws.close();
     }
   }
 }