diff --git a/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java b/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java index 2febbb46667..f264128696e 100644 --- a/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java +++ b/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessor.java @@ -184,6 +184,7 @@ private static final class Worker implements Runnable { private volatile boolean continueWork = true; private final ArrayList batch; private final long maxQueueSize; + private final AtomicInteger droppedSpanCount = new AtomicInteger(0); private Worker( SpanExporter spanExporter, @@ -212,6 +213,7 @@ private void addSpan(ReadableSpan span) { spanProcessorInstrumentation.buildQueueMetricsOnce(maxQueueSize, queue::size); if (!queue.offer(span)) { spanProcessorInstrumentation.dropSpans(1); + droppedSpanCount.incrementAndGet(); } else { if (queueSize.incrementAndGet() >= spansNeeded.get()) { signal.offer(true); @@ -315,6 +317,18 @@ private void exportCurrentBatch() { return; } + int dropped = droppedSpanCount.getAndSet(0); + if (dropped > 0) { + logger.log( + Level.WARNING, + "BatchSpanProcessor dropped " + + dropped + + " span(s) since the last export because the queue is full" + + " (maxQueueSize=" + + maxQueueSize + + ")"); + } + String error = null; try { CompletableResultCode result = spanExporter.export(Collections.unmodifiableList(batch)); diff --git a/sdk/trace/src/test/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessorTest.java b/sdk/trace/src/test/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessorTest.java index 98bc45705b3..e51b8daf42b 100644 --- a/sdk/trace/src/test/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessorTest.java +++ b/sdk/trace/src/test/java/io/opentelemetry/sdk/trace/export/BatchSpanProcessorTest.java @@ -18,6 +18,7 @@ import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; +import io.github.netmikey.logunit.api.LogCapturer; import io.opentelemetry.api.internal.GuardedBy; import io.opentelemetry.api.trace.Span; import io.opentelemetry.api.trace.Tracer; @@ -42,11 +43,13 @@ import org.junit.jupiter.api.Test; import org.junit.jupiter.api.Timeout; import org.junit.jupiter.api.extension.ExtendWith; +import org.junit.jupiter.api.extension.RegisterExtension; import org.mockito.ArgumentMatchers; import org.mockito.Mock; import org.mockito.junit.jupiter.MockitoExtension; import org.mockito.junit.jupiter.MockitoSettings; import org.mockito.quality.Strictness; +import org.slf4j.event.Level; @SuppressWarnings("PreferJavaTimeOverload") @ExtendWith(MockitoExtension.class) @@ -62,9 +65,13 @@ class BatchSpanProcessorTest { @Mock private Sampler mockSampler; @Mock private SpanExporter mockSpanExporter; + @RegisterExtension + LogCapturer logs = LogCapturer.create().captureForType(BatchSpanProcessor.class); + @BeforeEach void setUp() { when(mockSpanExporter.shutdown()).thenReturn(CompletableResultCode.ofSuccess()); + when(mockSpanExporter.export(anyList())).thenReturn(CompletableResultCode.ofSuccess()); } @AfterEach @@ -232,6 +239,32 @@ void exportMoreSpansThanTheBufferSize() { span6.toSpanData())); } + @Test + void droppedSpanIsLogged() { + sdkTracerProvider = + SdkTracerProvider.builder() + .addSpanProcessor( + BatchSpanProcessor.builder(mockSpanExporter) + .setMaxQueueSize(1) + .setMaxExportBatchSize(1_000) + .setScheduleDelay(Duration.ofDays(1)) + .build()) + .build(); + + // Fill the queue with the first span, then drop 2 more. + createEndedSpan(SPAN_NAME_1); + createEndedSpan(SPAN_NAME_2); + createEndedSpan(SPAN_NAME_2); + + // Force export to trigger the drop count log. + sdkTracerProvider.forceFlush().join(10, TimeUnit.SECONDS); + + logs.assertContains( + loggingEvent -> loggingEvent.getLevel().equals(Level.WARN), + "BatchSpanProcessor dropped 2 span(s) since the last export" + + " because the queue is full (maxQueueSize=1)"); + } + @Test void forceExport() { WaitingSpanExporter waitingSpanExporter =