From 75b5c6b27ba70de7d9c6e302880c96c0c50726de Mon Sep 17 00:00:00 2001 From: iparadiso <111398937+iparadiso@users.noreply.github.com> Date: Wed, 16 Sep 2026 09:47:28 -0700 Subject: [PATCH] prevent writing to a Span after it finishes --- .../evcache/EVCacheTracingEventListener.java | 55 ++++++++++- .../EVCacheTracingEventListenerUnitTests.java | 96 +++++++++++++++++-- 2 files changed, 137 insertions(+), 14 deletions(-) diff --git a/evcache-zipkin-tracing/src/main/java/com/netflix/evcache/EVCacheTracingEventListener.java b/evcache-zipkin-tracing/src/main/java/com/netflix/evcache/EVCacheTracingEventListener.java index b88758d3..f93a5e4a 100644 --- a/evcache-zipkin-tracing/src/main/java/com/netflix/evcache/EVCacheTracingEventListener.java +++ b/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) { *

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. + * + *

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. + * + *

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: + * + *

+ * + *

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. + * + *

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; + + 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. diff --git a/evcache-zipkin-tracing/src/test/java/com/netflix/evcache/EVCacheTracingEventListenerUnitTests.java b/evcache-zipkin-tracing/src/test/java/com/netflix/evcache/EVCacheTracingEventListenerUnitTests.java index bbeb96b6..34cc9cef 100644 --- a/evcache-zipkin-tracing/src/test/java/com/netflix/evcache/EVCacheTracingEventListenerUnitTests.java +++ b/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 reportedSpans; + + /** The live MutableSpan handed to the reporter, kept by reference so later writes are visible. */ + List 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 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() { @@ -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 spans) { @@ -87,7 +106,7 @@ public void verifyCommonTags(List 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 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. + * + *

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. + * + *

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); + } }