prevent writing to a Span after it finishes

evcache-zipkin-tracing/src/main/java/com/netflix/evcache/EVCacheTracingEventListener.java

@@ -13,6 +13,7 @@
 
 import java.util.ArrayList;
 import java.util.List;
+import java.util.concurrent.atomic.AtomicReference;
 import java.util.stream.Collectors;
 
 /** Adds tracing tags for EvCache calls. */
@@ -35,7 +36,7 @@ public EVCacheTracingEventListener(EVCacheClientPoolManager poolManager, Tracer
   public void onStart(EVCacheEvent e) {
     try {
       Span clientSpan =
-          this.tracer.nextSpan().kind(Span.Kind.CLIENT).name(EVCACHE_SPAN_NAME).start();
+              this.tracer.nextSpan().kind(Span.Kind.CLIENT).name(EVCACHE_SPAN_NAME).start();
 
       // Return if tracing has been disabled
       if(clientSpan.isNoop()){
@@ -104,8 +105,11 @@ public void onStart(EVCacheEvent e) {
        * <p>As EVCache write operations are asynchronous and quorum based, we are avoiding attaching
        * clientSpan with tracer.spanInScope(...) method. Instead, we are storing the clientSpan as
        * an object in the EVCacheEvent's attributes.
+       *
+       * <p>The span is wrapped in a {@link PendingSpan} so only the first of onComplete/onError
+       * finishes it. See {@link #onFinishHelper}.
        */
-      e.setAttribute(CLIENT_SPAN_ATTRIBUTE_KEY, clientSpan);
+      e.setAttribute(CLIENT_SPAN_ATTRIBUTE_KEY, new PendingSpan(clientSpan));
     } catch (Exception exception) {
       logger.error("onStart exception", exception);
     }
@@ -138,15 +142,36 @@ public boolean onThrottle(EVCacheEvent e) throws EVCacheException {
     return false;
   }
 
+  /**
+   * Tags and finishes the span for this event, at most once.
+   *
+   * <p>EVCacheImpl fires both onComplete and onError for one event on several paths, so without the
+   * claim below the second callback mutates a span the reporter may already be encoding:
+   *
+   * <ul>
+   *   <li>async get -- handleMissData (endEvent) then handleException (eventError), in the same
+   *       CompletableFuture.handle(...) branch
+   *   <li>async bulk get -- handleFullCacheMiss then handleException, likewise
+   *   <li>append -- endEvent, then touchData(...) inside the same try whose catch calls eventError
+   *   <li>getAndTouch -- eventError twice in a row
+   * </ul>
+   *
+   * <p>The first callback wins, so an error reported by a later one is dropped. Recovering it means
+   * not firing both callbacks in EVCacheImpl.
+   */
   private void onFinishHelper(EVCacheEvent e, Throwable t) {
     Object clientSpanObj = e.getAttribute(CLIENT_SPAN_ATTRIBUTE_KEY);
 
-    // Return if the previously saved Client Span is null
-    if (clientSpanObj == null) {
+    // Also covers null. The attribute map is string-keyed and shared, so check the type.
+    if (!(clientSpanObj instanceof PendingSpan)) {
       return;
     }
 
-    Span clientSpan = (Span) clientSpanObj;
+    // Whoever claims it finishes it; any later callback for this event gets null and is a no-op.
+    Span clientSpan = ((PendingSpan) clientSpanObj).claim();
+    if (clientSpan == null) {
+      return;
+    }
 
     try {
       if (t != null) {
@@ -178,6 +203,26 @@ private void safeTag(Span span, String key, String value) {
     }
   }
 
+  /**
+   * A span that can be claimed exactly once.
+   *
+   * <p>EVCacheEvent's attribute map is an unsynchronized HashMap, so the claim cannot be a
+   * remove-and-check on the map itself.
+   */
+  private static final class PendingSpan {
+
+    private final AtomicReference<Span> span;
+
+    PendingSpan(Span span) {
+      this.span = new AtomicReference<>(span);
+    }
+
+    /** Returns the span to the first caller only; null for every caller after that. */
+    Span claim() {
+      return this.span.getAndSet(null);
+    }
+  }
+
   private long getDurationInMicroseconds(long durationInMillis) {
 
     // EVCacheEvent returns durationInMillis as -1 if endTime is not available.

evcache-zipkin-tracing/src/test/java/com/netflix/evcache/EVCacheTracingEventListenerUnitTests.java

@@ -1,6 +1,9 @@
 package com.netflix.evcache;
 
 import brave.Tracing;
+import brave.handler.MutableSpan;
+import brave.handler.SpanHandler;
+import brave.propagation.TraceContext;
 import com.netflix.evcache.event.EVCacheEvent;
 import com.netflix.evcache.pool.EVCacheClient;
 import com.netflix.evcache.pool.EVCacheClientPoolManager;
@@ -23,6 +26,10 @@
 public class EVCacheTracingEventListenerUnitTests {
 
   List<zipkin2.Span> reportedSpans;
+
+  /** The live MutableSpan handed to the reporter, kept by reference so later writes are visible. */
+  List<MutableSpan> handedOffSpans;
+
   EVCacheTracingEventListener tracingListener;
   EVCacheClient mockEVCacheClient;
   EVCacheEvent mockEVCacheEvent;
@@ -40,12 +47,12 @@ public void resetMocks() {
     when(mockEVCacheEvent.getAppName()).thenReturn("dummyAppName");
     when(mockEVCacheEvent.getCacheName()).thenReturn("dummyCacheName");
     when(mockEVCacheEvent.getEVCacheKeys())
-        .thenReturn(Arrays.asList(new EVCacheKey("dummyAppName", "dummyKey", "dummyCanonicalKey", null, null, null, null)));
+            .thenReturn(Arrays.asList(new EVCacheKey("dummyAppName", "dummyKey", "dummyCanonicalKey", null, null, null, null)));
     when(mockEVCacheEvent.getStatus()).thenReturn("success");
     when(mockEVCacheEvent.getDurationInMillis()).thenReturn(1L);
     when(mockEVCacheEvent.getTTL()).thenReturn(0);
     when(mockEVCacheEvent.getCachedData())
-        .thenReturn(new CachedData(1, "dummyData".getBytes(), 255));
+            .thenReturn(new CachedData(1, "dummyData".getBytes(), 255));
 
     Map<String, Object> eventAttributes = new HashMap<>();
     doAnswer(
@@ -59,8 +66,8 @@ public Void answer(InvocationOnMock invocation) throws Throwable {
                 return null;
               }
             })
-        .when(mockEVCacheEvent)
-        .setAttribute(any(), any());
+            .when(mockEVCacheEvent)
+            .setAttribute(any(), any());
 
     doAnswer(
             new Answer<Object>() {
@@ -71,14 +78,26 @@ public Object answer(InvocationOnMock invocation) throws Throwable {
                 return eventAttributes.get(key);
               }
             })
-        .when(mockEVCacheEvent)
-        .getAttribute(any());
+            .when(mockEVCacheEvent)
+            .getAttribute(any());
 
     reportedSpans = new ArrayList<>();
-    Tracing tracing = Tracing.newBuilder().spanReporter(reportedSpans::add).build();
+    handedOffSpans = new ArrayList<>();
+    Tracing tracing =
+            Tracing.newBuilder()
+                    .addSpanHandler(
+                            new SpanHandler() {
+                              @Override
+                              public boolean end(TraceContext context, MutableSpan span, Cause cause) {
+                                handedOffSpans.add(span);
+                                return true;
+                              }
+                            })
+                    .spanReporter(reportedSpans::add)
+                    .build();
 
     tracingListener =
-        new EVCacheTracingEventListener(mock(EVCacheClientPoolManager.class), tracing.tracer());
+            new EVCacheTracingEventListener(mock(EVCacheClientPoolManager.class), tracing.tracer());
   }
 
   public void verifyCommonTags(List<zipkin2.Span> spans) {
@@ -87,7 +106,7 @@ public void verifyCommonTags(List<zipkin2.Span> spans) {
 
     Assert.assertEquals(span.kind(), Span.Kind.CLIENT, "Span Kind are not equal");
     Assert.assertEquals(
-        span.name(), EVCacheTracingEventListener.EVCACHE_SPAN_NAME, "Cache name are not equal");
+            span.name(), EVCacheTracingEventListener.EVCACHE_SPAN_NAME, "Cache name are not equal");
 
     Map<String, String> tags = span.tags();
     Assert.assertTrue(tags.containsKey(EVCacheTracingTags.APP_NAME), "APP_NAME tag is missing");
@@ -123,4 +142,63 @@ public void testEVCacheListenerOnError() {
     verifyCommonTags(reportedSpans);
     verifyErrorTags(reportedSpans);
   }
+
+  /**
+   * A later callback must not touch a span that has already been handed off. See
+   * EVCacheTracingEventListener#onFinishHelper for the paths that fire both.
+   *
+   * <p>Asserts on the handed-off MutableSpan, not the reported zipkin2.Span: the conversion happens
+   * at report time, so a post-finish write is invisible there.
+   */
+  @Test
+  public void testOnErrorAfterOnCompleteDoesNotMutateFinishedSpan() {
+    tracingListener.onStart(mockEVCacheEvent);
+    tracingListener.onComplete(mockEVCacheEvent);
+
+    Assert.assertEquals(handedOffSpans.size(), 1, "Expected exactly one span to be handed off");
+    MutableSpan handedOff = handedOffSpans.get(0);
+    int tagCountAtHandoff = handedOff.tagCount();
+
+    tracingListener.onError(mockEVCacheEvent, new RuntimeException("Unexpected Error"));
+
+    Assert.assertEquals(
+            handedOff.tagCount(), tagCountAtHandoff, "A tag was added after the span was handed off");
+    Assert.assertNull(
+            handedOff.tag(EVCacheTracingTags.ERROR),
+            "ERROR tag was written to a span that was already finished");
+    Assert.assertEquals(
+            handedOffSpans.size(), 1, "The span was handed off more than once");
+  }
+
+  /**
+   * The claim is order independent: whichever callback arrives first owns the span.
+   *
+   * <p>This direction adds no new tag key, so a tag count alone cannot detect a second pass. The
+   * status is changed between the callbacks to make one show up as an overwritten value.
+   */
+  @Test
+  public void testOnCompleteAfterOnErrorDoesNotMutateFinishedSpan() {
+    tracingListener.onStart(mockEVCacheEvent);
+    tracingListener.onError(mockEVCacheEvent, new RuntimeException("Unexpected Error"));
+
+    Assert.assertEquals(handedOffSpans.size(), 1, "Expected exactly one span to be handed off");
+    MutableSpan handedOff = handedOffSpans.get(0);
+    int tagCountAtHandoff = handedOff.tagCount();
+    String statusAtHandoff = handedOff.tag(EVCacheTracingTags.STATUS);
+
+    when(mockEVCacheEvent.getStatus()).thenReturn("statusWrittenAfterHandoff");
+    tracingListener.onComplete(mockEVCacheEvent);
+
+    Assert.assertEquals(
+            handedOff.tagCount(), tagCountAtHandoff, "A tag was added after the span was handed off");
+    Assert.assertEquals(
+            handedOff.tag(EVCacheTracingTags.STATUS),
+            statusAtHandoff,
+            "STATUS tag was overwritten on a span that was already finished");
+    Assert.assertEquals(handedOffSpans.size(), 1, "The span was handed off more than once");
+
+    // The first callback still recorded everything it should have.
+    verifyCommonTags(reportedSpans);
+    verifyErrorTags(reportedSpans);
+  }
 }