-
Notifications
You must be signed in to change notification settings - Fork 964
Add rate‑limited log warning when BatchSpanProcessor drops spans #8167
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 1 commit
ff11a8b
912e997
d14a2cc
ad025e3
903425f
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -11,6 +11,7 @@ | |
| import io.opentelemetry.sdk.common.InternalTelemetryVersion; | ||
| import io.opentelemetry.sdk.common.internal.ComponentId; | ||
| import io.opentelemetry.sdk.common.internal.DaemonThreadFactory; | ||
| import io.opentelemetry.sdk.common.internal.ThrottlingLogger; | ||
| import io.opentelemetry.sdk.common.internal.ThrowableUtil; | ||
| import io.opentelemetry.sdk.trace.ReadWriteSpan; | ||
| import io.opentelemetry.sdk.trace.ReadableSpan; | ||
|
|
@@ -46,6 +47,7 @@ public final class BatchSpanProcessor implements SpanProcessor { | |
| ComponentId.generateLazy("batching_span_processor"); | ||
|
|
||
| private static final Logger logger = Logger.getLogger(BatchSpanProcessor.class.getName()); | ||
| private static final ThrottlingLogger throttledLogger = new ThrottlingLogger(logger); | ||
|
|
||
| private static final String WORKER_THREAD_NAME = | ||
| BatchSpanProcessor.class.getSimpleName() + "_WorkerThread"; | ||
|
|
@@ -212,6 +214,11 @@ private void addSpan(ReadableSpan span) { | |
| spanProcessorInstrumentation.buildQueueMetricsOnce(maxQueueSize, queue::size); | ||
| if (!queue.offer(span)) { | ||
| spanProcessorInstrumentation.dropSpans(1); | ||
| throttledLogger.log( | ||
| Level.WARNING, | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Isn't warning too high level? I think INFO would be enough.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Good point. I think WARNING is appropriate here because dropped spans represent actual data loss, which impacts observability. This warrants immediate attention from operators in production. Since we're using However, if the team prefers INFO, I'm happy to adjust. Please let me know. |
||
| "BatchSpanProcessor dropped a span because the queue is full (maxQueueSize=" | ||
| + maxQueueSize | ||
| + ")"); | ||
| } else { | ||
| if (queueSize.incrementAndGet() >= spansNeeded.get()) { | ||
| signal.offer(true); | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -21,6 +21,7 @@ | |
| import io.opentelemetry.api.internal.GuardedBy; | ||
| import io.opentelemetry.api.trace.Span; | ||
| import io.opentelemetry.api.trace.Tracer; | ||
| import io.github.netmikey.logunit.api.LogCapturer; | ||
| import io.opentelemetry.internal.testing.slf4j.SuppressLogger; | ||
| import io.opentelemetry.sdk.common.CompletableResultCode; | ||
| import io.opentelemetry.sdk.trace.ReadableSpan; | ||
|
|
@@ -29,6 +30,7 @@ | |
| import io.opentelemetry.sdk.trace.samplers.Sampler; | ||
| import io.opentelemetry.sdk.trace.samplers.SamplingResult; | ||
| import java.time.Duration; | ||
| import org.slf4j.event.Level; | ||
| import java.util.ArrayList; | ||
| import java.util.Arrays; | ||
| import java.util.Collection; | ||
|
|
@@ -42,6 +44,7 @@ | |
| 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; | ||
|
|
@@ -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,30 @@ 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(); | ||
|
|
||
| // Add two spans quickly to trigger a drop when the queue is full. | ||
| createEndedSpan(SPAN_NAME_1); | ||
| createEndedSpan(SPAN_NAME_2); | ||
|
|
||
| await() | ||
| .untilAsserted( | ||
| () -> | ||
| logs.assertContains( | ||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Seems reasonable to assert the whole message, especially since it has some dynamic parts
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Thanks for the review, @anuraaga! Good catches on the test. I've updated it. @jkwatson @jack-berg -- on the question about Would appreciate another look when you get a chance! |
||
| loggingEvent -> loggingEvent.getLevel().equals(Level.WARN), | ||
| "BatchSpanProcessor dropped a span")); | ||
| } | ||
|
|
||
| @Test | ||
| void forceExport() { | ||
| WaitingSpanExporter waitingSpanExporter = | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
throttlingLogger would be a better name.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Good catch! I've updated the variable name from throttledLogger to throttlingLogger to better reflect that this logger performs throttling (matching the active form of the class name ThrottlingLogger).