Added SpanProcessor OnEnding callback (#6367)

Co-authored-by: jack-berg <34418638+jack-berg@users.noreply.github.com>
This commit is contained in:
Jonas Kunz 2024-09-04 20:52:09 +02:00 committed by GitHub
parent bc2fad4cf3
commit 09de4bd105
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
6 changed files with 313 additions and 25 deletions

View File

@ -7,6 +7,7 @@ package io.opentelemetry.sdk.trace;
import io.opentelemetry.context.Context;
import io.opentelemetry.sdk.common.CompletableResultCode;
import io.opentelemetry.sdk.trace.internal.ExtendedSpanProcessor;
import java.util.ArrayList;
import java.util.List;
import java.util.Objects;
@ -16,8 +17,9 @@ import java.util.concurrent.atomic.AtomicBoolean;
* Implementation of the {@code SpanProcessor} that simply forwards all received events to a list of
* {@code SpanProcessor}s.
*/
final class MultiSpanProcessor implements SpanProcessor {
final class MultiSpanProcessor implements ExtendedSpanProcessor {
private final List<SpanProcessor> spanProcessorsStart;
private final List<ExtendedSpanProcessor> spanProcessorsEnding;
private final List<SpanProcessor> spanProcessorsEnd;
private final List<SpanProcessor> spanProcessorsAll;
private final AtomicBoolean isShutdown = new AtomicBoolean(false);
@ -58,6 +60,18 @@ final class MultiSpanProcessor implements SpanProcessor {
return !spanProcessorsEnd.isEmpty();
}
@Override
public void onEnding(ReadWriteSpan span) {
for (ExtendedSpanProcessor spanProcessor : spanProcessorsEnding) {
spanProcessor.onEnding(span);
}
}
@Override
public boolean isOnEndingRequired() {
return !spanProcessorsEnding.isEmpty();
}
@Override
public CompletableResultCode shutdown() {
if (isShutdown.getAndSet(true)) {
@ -83,10 +97,17 @@ final class MultiSpanProcessor implements SpanProcessor {
this.spanProcessorsAll = spanProcessors;
this.spanProcessorsStart = new ArrayList<>(spanProcessorsAll.size());
this.spanProcessorsEnd = new ArrayList<>(spanProcessorsAll.size());
this.spanProcessorsEnding = new ArrayList<>(spanProcessorsAll.size());
for (SpanProcessor spanProcessor : spanProcessorsAll) {
if (spanProcessor.isStartRequired()) {
spanProcessorsStart.add(spanProcessor);
}
if (spanProcessor instanceof ExtendedSpanProcessor) {
ExtendedSpanProcessor extendedSpanProcessor = (ExtendedSpanProcessor) spanProcessor;
if (extendedSpanProcessor.isOnEndingRequired()) {
spanProcessorsEnding.add(extendedSpanProcessor);
}
}
if (spanProcessor.isEndRequired()) {
spanProcessorsEnd.add(spanProcessor);
}
@ -98,6 +119,8 @@ final class MultiSpanProcessor implements SpanProcessor {
return "MultiSpanProcessor{"
+ "spanProcessorsStart="
+ spanProcessorsStart
+ ", spanProcessorsEnding="
+ spanProcessorsEnding
+ ", spanProcessorsEnd="
+ spanProcessorsEnd
+ ", spanProcessorsAll="

View File

@ -23,6 +23,7 @@ import io.opentelemetry.sdk.trace.data.EventData;
import io.opentelemetry.sdk.trace.data.LinkData;
import io.opentelemetry.sdk.trace.data.SpanData;
import io.opentelemetry.sdk.trace.data.StatusData;
import io.opentelemetry.sdk.trace.internal.ExtendedSpanProcessor;
import io.opentelemetry.sdk.trace.internal.data.ExceptionEventData;
import java.util.ArrayList;
import java.util.Collections;
@ -95,9 +96,24 @@ final class SdkSpan implements ReadWriteSpan {
@GuardedBy("lock")
private long endEpochNanos;
// True if the span is ended.
private enum EndState {
NOT_ENDED,
ENDING,
ENDED
}
@GuardedBy("lock")
private boolean hasEnded;
private EndState hasEnded;
/**
* The thread on which {@link #end()} is called and which will be invoking the {@link
* SpanProcessor}s. This field is used to ensure that only this thread may modify the span while
* it is in state {@link EndState#ENDING} to prevent concurrent updates outside of {@link
* ExtendedSpanProcessor#onEnding(ReadWriteSpan)}.
*/
@GuardedBy("lock")
@Nullable
private Thread spanEndingThread;
private SdkSpan(
SpanContext context,
@ -122,7 +138,7 @@ final class SdkSpan implements ReadWriteSpan {
this.kind = kind;
this.spanProcessor = spanProcessor;
this.resource = resource;
this.hasEnded = false;
this.hasEnded = EndState.NOT_ENDED;
this.clock = clock;
this.startEpochNanos = startEpochNanos;
this.attributes = attributes;
@ -220,7 +236,7 @@ final class SdkSpan implements ReadWriteSpan {
status,
name,
endEpochNanos,
hasEnded);
hasEnded == EndState.ENDED);
}
}
@ -242,7 +258,7 @@ final class SdkSpan implements ReadWriteSpan {
@Override
public boolean hasEnded() {
synchronized (lock) {
return hasEnded;
return hasEnded == EndState.ENDED;
}
}
@ -288,7 +304,7 @@ final class SdkSpan implements ReadWriteSpan {
@Override
public long getLatencyNanos() {
synchronized (lock) {
return (hasEnded ? endEpochNanos : clock.now()) - startEpochNanos;
return (hasEnded == EndState.NOT_ENDED ? clock.now() : endEpochNanos) - startEpochNanos;
}
}
@ -303,7 +319,7 @@ final class SdkSpan implements ReadWriteSpan {
return this;
}
synchronized (lock) {
if (hasEnded) {
if (!isModifiableByCurrentThread()) {
logger.log(Level.FINE, "Calling setAttribute() on an ended Span.");
return this;
}
@ -318,6 +334,12 @@ final class SdkSpan implements ReadWriteSpan {
return this;
}
@GuardedBy("lock")
private boolean isModifiableByCurrentThread() {
return hasEnded == EndState.NOT_ENDED
|| (hasEnded == EndState.ENDING && Thread.currentThread() == spanEndingThread);
}
@Override
public ReadWriteSpan addEvent(String name) {
if (name == null) {
@ -380,7 +402,7 @@ final class SdkSpan implements ReadWriteSpan {
private void addTimedEvent(EventData timedEvent) {
synchronized (lock) {
if (hasEnded) {
if (!isModifiableByCurrentThread()) {
logger.log(Level.FINE, "Calling addEvent() on an ended Span.");
return;
}
@ -400,7 +422,7 @@ final class SdkSpan implements ReadWriteSpan {
return this;
}
synchronized (lock) {
if (hasEnded) {
if (!isModifiableByCurrentThread()) {
logger.log(Level.FINE, "Calling setStatus() on an ended Span.");
return this;
} else if (this.status.getStatusCode() == StatusCode.OK) {
@ -438,7 +460,7 @@ final class SdkSpan implements ReadWriteSpan {
return this;
}
synchronized (lock) {
if (hasEnded) {
if (!isModifiableByCurrentThread()) {
logger.log(Level.FINE, "Calling updateName() on an ended Span.");
return this;
}
@ -463,7 +485,7 @@ final class SdkSpan implements ReadWriteSpan {
spanLimits.getMaxNumberOfAttributesPerLink(),
spanLimits.getMaxAttributeValueLength()));
synchronized (lock) {
if (hasEnded) {
if (!isModifiableByCurrentThread()) {
logger.log(Level.FINE, "Calling addLink() on an ended Span.");
return this;
}
@ -493,12 +515,22 @@ final class SdkSpan implements ReadWriteSpan {
private void endInternal(long endEpochNanos) {
synchronized (lock) {
if (hasEnded) {
logger.log(Level.FINE, "Calling end() on an ended Span.");
if (hasEnded != EndState.NOT_ENDED) {
logger.log(Level.FINE, "Calling end() on an ended or ending Span.");
return;
}
this.endEpochNanos = endEpochNanos;
hasEnded = true;
spanEndingThread = Thread.currentThread();
hasEnded = EndState.ENDING;
}
if (spanProcessor instanceof ExtendedSpanProcessor) {
ExtendedSpanProcessor extendedSpanProcessor = (ExtendedSpanProcessor) spanProcessor;
if (extendedSpanProcessor.isOnEndingRequired()) {
extendedSpanProcessor.onEnding(this);
}
}
synchronized (lock) {
hasEnded = EndState.ENDED;
}
if (spanProcessor.isEndRequired()) {
spanProcessor.onEnd(this);
@ -508,7 +540,7 @@ final class SdkSpan implements ReadWriteSpan {
@Override
public boolean isRecording() {
synchronized (lock) {
return !hasEnded;
return hasEnded != EndState.ENDED;
}
}
@ -533,7 +565,7 @@ final class SdkSpan implements ReadWriteSpan {
// if the span has ended, then the events are unmodifiable
// so we can return them directly and save copying all the data.
if (hasEnded) {
if (hasEnded == EndState.ENDED) {
return Collections.unmodifiableList(events);
}
@ -547,7 +579,7 @@ final class SdkSpan implements ReadWriteSpan {
}
// if the span has ended, then the attributes are unmodifiable,
// so we can return them directly and save copying all the data.
if (hasEnded) {
if (hasEnded == EndState.ENDED) {
return attributes;
}
// otherwise, make a copy of the data into an immutable container.

View File

@ -0,0 +1,41 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.sdk.trace.internal;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.sdk.trace.ReadWriteSpan;
import io.opentelemetry.sdk.trace.ReadableSpan;
import io.opentelemetry.sdk.trace.SpanProcessor;
/**
* Extended {@link SpanProcessor} with experimental APIs.
*
* <p>This class is internal and is hence not for public use. Its APIs are unstable and can change
* at any time.
*/
public interface ExtendedSpanProcessor extends SpanProcessor {
/**
* Called when a {@link io.opentelemetry.api.trace.Span} is ended, but before {@link
* SpanProcessor#onEnd(ReadableSpan)} is invoked with an immutable variant of this span. This
* means that the span will still be mutable. Note that the span will only be modifiable
* synchronously from this callback, concurrent modifications from other threads will be
* prevented. Only called if {@link Span#isRecording()} returns true.
*
* <p>This method is called synchronously on the execution thread, should not throw or block the
* execution thread.
*
* @param span the {@code Span} that is just about to be ended.
*/
void onEnding(ReadWriteSpan span);
/**
* Returns {@code true} if this {@link SpanProcessor} requires onEnding events.
*
* @return {@code true} if this {@link SpanProcessor} requires onEnding events.
*/
boolean isOnEndingRequired();
}

View File

@ -14,6 +14,7 @@ import static org.mockito.Mockito.when;
import io.opentelemetry.context.Context;
import io.opentelemetry.sdk.common.CompletableResultCode;
import io.opentelemetry.sdk.trace.internal.ExtendedSpanProcessor;
import java.util.Arrays;
import java.util.Collections;
import org.junit.jupiter.api.BeforeEach;
@ -27,18 +28,20 @@ import org.mockito.quality.Strictness;
@ExtendWith(MockitoExtension.class)
@MockitoSettings(strictness = Strictness.LENIENT)
class MultiSpanProcessorTest {
@Mock private SpanProcessor spanProcessor1;
@Mock private SpanProcessor spanProcessor2;
@Mock private ExtendedSpanProcessor spanProcessor1;
@Mock private ExtendedSpanProcessor spanProcessor2;
@Mock private ReadableSpan readableSpan;
@Mock private ReadWriteSpan readWriteSpan;
@BeforeEach
void setUp() {
when(spanProcessor1.isStartRequired()).thenReturn(true);
when(spanProcessor1.isOnEndingRequired()).thenReturn(true);
when(spanProcessor1.isEndRequired()).thenReturn(true);
when(spanProcessor1.forceFlush()).thenReturn(CompletableResultCode.ofSuccess());
when(spanProcessor1.shutdown()).thenReturn(CompletableResultCode.ofSuccess());
when(spanProcessor2.isStartRequired()).thenReturn(true);
when(spanProcessor2.isOnEndingRequired()).thenReturn(true);
when(spanProcessor2.isEndRequired()).thenReturn(true);
when(spanProcessor2.forceFlush()).thenReturn(CompletableResultCode.ofSuccess());
when(spanProcessor2.shutdown()).thenReturn(CompletableResultCode.ofSuccess());
@ -61,12 +64,17 @@ class MultiSpanProcessorTest {
@Test
void twoSpanProcessor() {
SpanProcessor multiSpanProcessor =
ExtendedSpanProcessor multiSpanProcessor =
(ExtendedSpanProcessor)
SpanProcessor.composite(Arrays.asList(spanProcessor1, spanProcessor2));
multiSpanProcessor.onStart(Context.root(), readWriteSpan);
verify(spanProcessor1).onStart(same(Context.root()), same(readWriteSpan));
verify(spanProcessor2).onStart(same(Context.root()), same(readWriteSpan));
multiSpanProcessor.onEnding(readWriteSpan);
verify(spanProcessor1).onEnding(same(readWriteSpan));
verify(spanProcessor2).onEnding(same(readWriteSpan));
multiSpanProcessor.onEnd(readableSpan);
verify(spanProcessor1).onEnd(same(readableSpan));
verify(spanProcessor2).onEnd(same(readableSpan));
@ -83,8 +91,10 @@ class MultiSpanProcessorTest {
@Test
void twoSpanProcessor_DifferentRequirements() {
when(spanProcessor1.isEndRequired()).thenReturn(false);
when(spanProcessor2.isOnEndingRequired()).thenReturn(false);
when(spanProcessor2.isStartRequired()).thenReturn(false);
SpanProcessor multiSpanProcessor =
ExtendedSpanProcessor multiSpanProcessor =
(ExtendedSpanProcessor)
SpanProcessor.composite(Arrays.asList(spanProcessor1, spanProcessor2));
assertThat(multiSpanProcessor.isStartRequired()).isTrue();
@ -94,6 +104,10 @@ class MultiSpanProcessorTest {
verify(spanProcessor1).onStart(same(Context.root()), same(readWriteSpan));
verify(spanProcessor2, times(0)).onStart(any(Context.class), any(ReadWriteSpan.class));
multiSpanProcessor.onEnding(readWriteSpan);
verify(spanProcessor1).onEnding(same(readWriteSpan));
verify(spanProcessor2, times(0)).onEnding(any(ReadWriteSpan.class));
multiSpanProcessor.onEnd(readableSpan);
verify(spanProcessor1, times(0)).onEnd(any(ReadableSpan.class));
verify(spanProcessor2).onEnd(same(readableSpan));
@ -117,6 +131,7 @@ class MultiSpanProcessorTest {
.hasToString(
"MultiSpanProcessor{"
+ "spanProcessorsStart=[spanProcessor1, spanProcessor1], "
+ "spanProcessorsEnding=[spanProcessor1, spanProcessor1], "
+ "spanProcessorsEnd=[spanProcessor1, spanProcessor1], "
+ "spanProcessorsAll=[spanProcessor1, spanProcessor1]}");
}

View File

@ -18,6 +18,8 @@ import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.assertThatCode;
import static org.assertj.core.api.Assertions.assertThatThrownBy;
import static org.mockito.ArgumentMatchers.any;
import static org.mockito.ArgumentMatchers.same;
import static org.mockito.Mockito.doAnswer;
import static org.mockito.Mockito.never;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.when;
@ -42,6 +44,7 @@ import io.opentelemetry.sdk.trace.data.EventData;
import io.opentelemetry.sdk.trace.data.LinkData;
import io.opentelemetry.sdk.trace.data.SpanData;
import io.opentelemetry.sdk.trace.data.StatusData;
import io.opentelemetry.sdk.trace.internal.ExtendedSpanProcessor;
import io.opentelemetry.sdk.trace.internal.data.ExceptionEventData;
import java.io.PrintWriter;
import java.io.StringWriter;
@ -58,6 +61,8 @@ import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicLong;
import java.util.stream.IntStream;
import javax.annotation.Nullable;
import org.junit.jupiter.api.BeforeEach;
@ -90,7 +95,7 @@ class SdkSpanTest {
private final Map<AttributeKey, Object> attributes = new HashMap<>();
private Attributes expectedAttributes;
private final LinkData link = LinkData.create(spanContext);
@Mock private SpanProcessor spanProcessor;
@Mock private ExtendedSpanProcessor spanProcessor;
private TestClock testClock;
@ -107,6 +112,7 @@ class SdkSpanTest {
expectedAttributes = builder.build();
testClock = TestClock.create(Instant.ofEpochSecond(0, START_EPOCH_NANOS));
when(spanProcessor.isStartRequired()).thenReturn(true);
when(spanProcessor.isOnEndingRequired()).thenReturn(true);
when(spanProcessor.isEndRequired()).thenReturn(true);
}
@ -140,6 +146,92 @@ class SdkSpanTest {
assertThat(span.hasEnded()).isTrue();
}
@Test
void onEnding_spanStillMutable() {
SdkSpan span = createTestSpan(SpanKind.INTERNAL);
AttributeKey<String> dummyAttrib = AttributeKey.stringKey("processor_foo");
AtomicBoolean endedStateInProcessor = new AtomicBoolean();
doAnswer(
invocation -> {
ReadWriteSpan sp = invocation.getArgument(0, ReadWriteSpan.class);
assertThat(sp.hasEnded()).isFalse();
sp.end(); // should have no effect, nested end should be detected
endedStateInProcessor.set(sp.hasEnded());
sp.setAttribute(dummyAttrib, "bar");
return null;
})
.when(spanProcessor)
.onEnding(any());
span.end();
verify(spanProcessor).onEnding(same(span));
assertThat(span.hasEnded()).isTrue();
assertThat(endedStateInProcessor.get()).isFalse();
assertThat(span.getAttribute(dummyAttrib)).isEqualTo("bar");
}
@Test
void onEnding_concurrentModificationsPrevented() {
SdkSpan span = createTestSpan(SpanKind.INTERNAL);
AttributeKey<String> syncAttrib = AttributeKey.stringKey("sync_foo");
AttributeKey<String> concurrentAttrib = AttributeKey.stringKey("concurrent_foo");
doAnswer(
invocation -> {
ReadWriteSpan sp = invocation.getArgument(0, ReadWriteSpan.class);
Thread concurrent =
new Thread(
() -> {
sp.setAttribute(concurrentAttrib, "concurrent_bar");
});
concurrent.start();
concurrent.join();
sp.setAttribute(syncAttrib, "sync_bar");
return null;
})
.when(spanProcessor)
.onEnding(any());
span.end();
verify(spanProcessor).onEnding(same(span));
assertThat(span.getAttribute(concurrentAttrib)).isNull();
assertThat(span.getAttribute(syncAttrib)).isEqualTo("sync_bar");
}
@Test
void onEnding_latencyPinned() {
SdkSpan span = createTestSpan(SpanKind.INTERNAL);
AtomicLong spanLatencyInProcessor = new AtomicLong();
doAnswer(
invocation -> {
ReadWriteSpan sp = invocation.getArgument(0, ReadWriteSpan.class);
testClock.advance(Duration.ofSeconds(100));
spanLatencyInProcessor.set(sp.getLatencyNanos());
return null;
})
.when(spanProcessor)
.onEnding(any());
testClock.advance(Duration.ofSeconds(1));
long expectedDuration = testClock.now() - START_EPOCH_NANOS;
assertThat(span.getLatencyNanos()).isEqualTo(expectedDuration);
span.end();
verify(spanProcessor).onEnding(same(span));
assertThat(span.hasEnded()).isTrue();
assertThat(span.getLatencyNanos()).isEqualTo(expectedDuration);
assertThat(spanLatencyInProcessor.get()).isEqualTo(expectedDuration);
}
@Test
void toSpanData_ActiveSpan() {
SdkSpan span = createTestSpan(SpanKind.INTERNAL);

View File

@ -0,0 +1,85 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/
package io.opentelemetry.sdk.trace.internal;
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;
import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.Tracer;
import io.opentelemetry.context.Context;
import io.opentelemetry.sdk.testing.exporter.InMemorySpanExporter;
import io.opentelemetry.sdk.trace.ReadWriteSpan;
import io.opentelemetry.sdk.trace.ReadableSpan;
import io.opentelemetry.sdk.trace.SdkTracerProvider;
import io.opentelemetry.sdk.trace.export.SimpleSpanProcessor;
import org.junit.jupiter.api.Test;
/** Demonstrating usage of {@link ExtendedSpanProcessor}. */
class ExtendedSpanProcessorUsageTest {
private static final AttributeKey<String> FOO_KEY = AttributeKey.stringKey("foo");
private static final AttributeKey<String> BAR_KEY = AttributeKey.stringKey("bar");
private static class CopyFooToBarProcessor implements ExtendedSpanProcessor {
@Override
public void onStart(Context parentContext, ReadWriteSpan span) {}
@Override
public boolean isStartRequired() {
return false;
}
@Override
public void onEnd(ReadableSpan span) {}
@Override
public boolean isEndRequired() {
return false;
}
@Override
public void onEnding(ReadWriteSpan span) {
String val = span.getAttribute(FOO_KEY);
span.setAttribute(BAR_KEY, val);
}
@Override
public boolean isOnEndingRequired() {
return true;
}
}
@Test
void extendedSpanProcessorUsage() {
InMemorySpanExporter exporter = InMemorySpanExporter.create();
try (SdkTracerProvider tracerProvider =
SdkTracerProvider.builder()
.addSpanProcessor(SimpleSpanProcessor.create(exporter))
.addSpanProcessor(new CopyFooToBarProcessor())
.build()) {
Tracer tracer = tracerProvider.get("dummy-tracer");
Span span = tracer.spanBuilder("my-span").startSpan();
span.setAttribute(FOO_KEY, "Hello!");
span.end();
assertThat(exporter.getFinishedSpanItems())
.hasSize(1)
.first()
.satisfies(
spanData -> {
assertThat(spanData.getAttributes())
.containsEntry(FOO_KEY, "Hello!")
.containsEntry(BAR_KEY, "Hello!");
});
}
}
}