diff --git a/dd-trace-core/src/main/java/datadog/trace/common/writer/RemoteWriter.java b/dd-trace-core/src/main/java/datadog/trace/common/writer/RemoteWriter.java index 2aa8ca57ec0..c4c6801bd05 100644 --- a/dd-trace-core/src/main/java/datadog/trace/common/writer/RemoteWriter.java +++ b/dd-trace-core/src/main/java/datadog/trace/common/writer/RemoteWriter.java @@ -94,7 +94,27 @@ public void write(final List trace) { if (log.isDebugEnabled()) { log.debug("Dropped due to a buffer overflow: {}", trace); } else { - rlLog.warn("Dropped due to a buffer overflow: [{} spans]", trace.size()); + rlLog.warn( + "Dropped a kept trace due to a buffer overflow: [{} spans]." + + " Traces are being produced faster than they can be sent to the agent.", + trace.size()); + } + handleDroppedTrace(trace); + break; + case DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT: + // Only sampled-out traces were lost, so this is not worth alarming the user over. + log.debug("Dropped a sampled-out trace due to a buffer overflow: {}", trace); + handleDroppedTrace(trace); + break; + case DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN: + if (log.isDebugEnabled()) { + log.debug( + "Dropped a single span sampling candidate due to a buffer overflow: {}", trace); + } else { + rlLog.warn( + "Dropped a single span sampling candidate due to a buffer overflow: [{} spans]." + + " Traces are being produced faster than they can be sent to the agent.", + trace.size()); } handleDroppedTrace(trace); break; diff --git a/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/Prioritization.java b/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/Prioritization.java index a9487f81d74..1475dddbdb9 100644 --- a/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/Prioritization.java +++ b/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/Prioritization.java @@ -85,6 +85,10 @@ private EnsureTraceStrategy( @Override public > PublishResult publish( T root, int priority, final List trace) { + if (root.isForceKeep()) { + blockingOffer(primary, trace); + return PublishResult.ENQUEUED_FOR_SERIALIZATION; + } switch (priority) { case SAMPLER_DROP: case USER_DROP: @@ -92,11 +96,11 @@ public > PublishResult publish( // send dropped traces for single span sampling return spanSampling.offer(trace) ? PublishResult.ENQUEUED_FOR_SINGLE_SPAN_SAMPLING - : PublishResult.DROPPED_BUFFER_OVERFLOW; + : PublishResult.DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN; } return secondary.offer(trace) ? PublishResult.ENQUEUED_FOR_SERIALIZATION - : PublishResult.DROPPED_BUFFER_OVERFLOW; + : PublishResult.DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT; default: blockingOffer(primary, trace); return PublishResult.ENQUEUED_FOR_SERIALIZATION; @@ -135,14 +139,14 @@ public > PublishResult publish(T root, int priority, List< // send dropped traces for single span sampling return spanSampling.offer(trace) ? PublishResult.ENQUEUED_FOR_SINGLE_SPAN_SAMPLING - : PublishResult.DROPPED_BUFFER_OVERFLOW; + : PublishResult.DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN; } if (droppingPolicy.active()) { return PublishResult.DROPPED_BY_POLICY; } return secondary.offer(trace) ? PublishResult.ENQUEUED_FOR_SERIALIZATION - : PublishResult.DROPPED_BUFFER_OVERFLOW; + : PublishResult.DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT; default: return primary.offer(trace) ? PublishResult.ENQUEUED_FOR_SERIALIZATION diff --git a/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/PrioritizationStrategy.java b/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/PrioritizationStrategy.java index 9fe7fe24c25..aabfad9d9d8 100644 --- a/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/PrioritizationStrategy.java +++ b/dd-trace-core/src/main/java/datadog/trace/common/writer/ddagent/PrioritizationStrategy.java @@ -10,7 +10,25 @@ enum PublishResult { ENQUEUED_FOR_SERIALIZATION, ENQUEUED_FOR_SINGLE_SPAN_SAMPLING, DROPPED_BY_POLICY, - DROPPED_BUFFER_OVERFLOW + /** + * A trace that sampling decided to keep could not be enqueued because the queue was full. The + * trace is lost and will be missing from the UI. + */ + DROPPED_BUFFER_OVERFLOW, + /** + * A trace that sampling already decided to drop could not be enqueued because the queue was + * full. No kept trace is lost. Such traces are only enqueued at all when the agent computes + * trace stats itself, so the sole consequence is a small loss of accuracy in agent-computed + * stats; with client-side stats enabled they are discarded before reaching a queue. + */ + DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT, + /** + * A trace that sampling decided to drop could not be offered to the single span sampling queue + * because that queue was full. Unlike {@link #DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT}, this is not + * a stats-only loss: the trace's spans were candidates to be individually kept by single span + * sampling, so losing them can mean losing spans that would otherwise have reached the UI. + */ + DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN } > PublishResult publish(T root, int priority, List trace); diff --git a/dd-trace-core/src/test/java/datadog/trace/common/writer/DDAgentWriterTest.java b/dd-trace-core/src/test/java/datadog/trace/common/writer/DDAgentWriterTest.java index 873f80f9a48..ec781ff4131 100644 --- a/dd-trace-core/src/test/java/datadog/trace/common/writer/DDAgentWriterTest.java +++ b/dd-trace-core/src/test/java/datadog/trace/common/writer/DDAgentWriterTest.java @@ -147,9 +147,10 @@ void testWriterWritePublishForSingleSpanSampling() { } @TableTest({ - "scenario | publishResult ", - "buffer overflow | DROPPED_BUFFER_OVERFLOW", - "dropped by policy | DROPPED_BY_POLICY " + "scenario | publishResult ", + "buffer overflow | DROPPED_BUFFER_OVERFLOW ", + "buffer overflow (sampled out) | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT", + "dropped by policy | DROPPED_BY_POLICY " }) void testWriterWritePublishFails(PublishResult publishResult) { List trace = @@ -191,9 +192,10 @@ void testWriterWriteClosed() { } @TableTest({ - "scenario | publishResult ", - "dropped by policy | DROPPED_BY_POLICY ", - "buffer overflow | DROPPED_BUFFER_OVERFLOW" + "scenario | publishResult ", + "dropped by policy | DROPPED_BY_POLICY ", + "buffer overflow | DROPPED_BUFFER_OVERFLOW ", + "buffer overflow (sampled out) | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT" }) void testDroppedTraceIsCounted(PublishResult publishResult) { // setup - use local mocks to avoid interference with instance-level mocks diff --git a/dd-trace-core/src/test/java/datadog/trace/common/writer/DDIntakeWriterTest.java b/dd-trace-core/src/test/java/datadog/trace/common/writer/DDIntakeWriterTest.java index eb7f00ac75e..1a47599ee01 100644 --- a/dd-trace-core/src/test/java/datadog/trace/common/writer/DDIntakeWriterTest.java +++ b/dd-trace-core/src/test/java/datadog/trace/common/writer/DDIntakeWriterTest.java @@ -149,9 +149,10 @@ void testWriterWritePublishForSingleSpanSampling() { } @TableTest({ - "scenario | publishResult ", - "buffer overflow | DROPPED_BUFFER_OVERFLOW", - "dropped by policy | DROPPED_BY_POLICY " + "scenario | publishResult ", + "buffer overflow | DROPPED_BUFFER_OVERFLOW ", + "buffer overflow (sampled out) | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT", + "dropped by policy | DROPPED_BY_POLICY " }) void testWriterWritePublishFails(PublishResult publishResult) { List trace = @@ -196,9 +197,10 @@ void testWriterWriteClosed() { } @TableTest({ - "scenario | publishResult ", - "dropped by policy | DROPPED_BY_POLICY ", - "buffer overflow | DROPPED_BUFFER_OVERFLOW" + "scenario | publishResult ", + "dropped by policy | DROPPED_BY_POLICY ", + "buffer overflow | DROPPED_BUFFER_OVERFLOW ", + "buffer overflow (sampled out) | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT" }) void testDroppedTraceIsCounted(PublishResult publishResult) { // setup - use local mocks diff --git a/dd-trace-core/src/test/java/datadog/trace/common/writer/PrioritizationTest.java b/dd-trace-core/src/test/java/datadog/trace/common/writer/PrioritizationTest.java index 7a9a52cd144..cc1a16e9b94 100644 --- a/dd-trace-core/src/test/java/datadog/trace/common/writer/PrioritizationTest.java +++ b/dd-trace-core/src/test/java/datadog/trace/common/writer/PrioritizationTest.java @@ -1,6 +1,5 @@ package datadog.trace.common.writer; -import static datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult.DROPPED_BUFFER_OVERFLOW; import static datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult.ENQUEUED_FOR_SERIALIZATION; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.mockito.ArgumentMatchers.any; @@ -65,17 +64,18 @@ void testEnsureTraceStrategyTriesToSendKeptAndUnsetPriorityTracesToPrimaryQueue( @SuppressWarnings("unchecked") @TableTest({ - "scenario | priority | primaryOffers | secondaryOffers", - "unset | PrioritySampling.UNSET | 1 | 0 ", - "drop | PrioritySampling.SAMPLER_DROP | 0 | 1 ", - "keep | PrioritySampling.SAMPLER_KEEP | 1 | 0 ", - "drop 2 | PrioritySampling.SAMPLER_DROP | 0 | 1 ", - "user keep | PrioritySampling.USER_KEEP | 1 | 0 " + "scenario | priority | primaryOffers | secondaryOffers | expectedResult ", + "unset | PrioritySampling.UNSET | 1 | 0 | DROPPED_BUFFER_OVERFLOW ", + "drop | PrioritySampling.SAMPLER_DROP | 0 | 1 | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT", + "keep | PrioritySampling.SAMPLER_KEEP | 1 | 0 | DROPPED_BUFFER_OVERFLOW ", + "drop 2 | PrioritySampling.SAMPLER_DROP | 0 | 1 | DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT", + "user keep | PrioritySampling.USER_KEEP | 1 | 0 | DROPPED_BUFFER_OVERFLOW " }) void testFastLaneStrategySendsKeptAndUnsetPriorityTracesToPrimaryQueue( @ConvertWith(PrioritySamplingConverter.class) int priority, int primaryOffers, - int secondaryOffers) { + int secondaryOffers, + PublishResult expectedResult) { List trace = Collections.emptyList(); Queue primary = mock(Queue.class); Queue secondary = mock(Queue.class); @@ -84,7 +84,7 @@ void testFastLaneStrategySendsKeptAndUnsetPriorityTracesToPrimaryQueue( PublishResult publishResult = fastLane.publish(mock(DDSpan.class), priority, trace); - assertEquals(DROPPED_BUFFER_OVERFLOW, publishResult); + assertEquals(expectedResult, publishResult); verify(primary, times(primaryOffers)).offer(trace); verify(secondary, times(secondaryOffers)).offer(trace); } @@ -160,27 +160,27 @@ void testDropStrategyRespectsForceKeep( @SuppressWarnings("unchecked") @TableTest({ - "scenario | primaryFull | priority | primaryOffers | singleSpanOffers | singleSpanFull | expectedResult ", - "unset full ss-not-full | true | PrioritySampling.UNSET | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop full ss-not-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "keep full ss-not-full | true | PrioritySampling.SAMPLER_KEEP | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop full 2 ss-not-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "ukeep full ss-not-full | true | PrioritySampling.USER_KEEP | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "unset nfull ss-not-full | false | PrioritySampling.UNSET | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop nfull ss-not-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "keep nfull ss-not-full | false | PrioritySampling.SAMPLER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop nfull 2 ss-not-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "ukeep nfull ss-not-full | false | PrioritySampling.USER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "unset full ss-full | true | PrioritySampling.UNSET | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop full ss-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "keep full ss-full | true | PrioritySampling.SAMPLER_KEEP | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop full 2 ss-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "ukeep full ss-full | true | PrioritySampling.USER_KEEP | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "unset nfull ss-full | false | PrioritySampling.UNSET | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop nfull ss-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "keep nfull ss-full | false | PrioritySampling.SAMPLER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop nfull 2 ss-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "ukeep nfull ss-full | false | PrioritySampling.USER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION " + "scenario | primaryFull | priority | primaryOffers | singleSpanOffers | singleSpanFull | expectedResult ", + "unset full ss-not-full | true | PrioritySampling.UNSET | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop full ss-not-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "keep full ss-not-full | true | PrioritySampling.SAMPLER_KEEP | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop full 2 ss-not-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "ukeep full ss-not-full | true | PrioritySampling.USER_KEEP | 2 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "unset nfull ss-not-full | false | PrioritySampling.UNSET | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop nfull ss-not-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "keep nfull ss-not-full | false | PrioritySampling.SAMPLER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop nfull 2 ss-not-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "ukeep nfull ss-not-full | false | PrioritySampling.USER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "unset full ss-full | true | PrioritySampling.UNSET | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop full ss-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "keep full ss-full | true | PrioritySampling.SAMPLER_KEEP | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop full 2 ss-full | true | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "ukeep full ss-full | true | PrioritySampling.USER_KEEP | 2 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "unset nfull ss-full | false | PrioritySampling.UNSET | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop nfull ss-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "keep nfull ss-full | false | PrioritySampling.SAMPLER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop nfull 2 ss-full | false | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "ukeep nfull ss-full | false | PrioritySampling.USER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION " }) void testEnsureTraceStrategyWithSpanSamplingQueue( boolean primaryFull, @@ -208,17 +208,17 @@ void testEnsureTraceStrategyWithSpanSamplingQueue( @SuppressWarnings("unchecked") @TableTest({ - "scenario | priority | primaryOffers | singleSpanOffers | singleSpanFull | expectedResult ", - "unset ss-not-full | PrioritySampling.UNSET | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop ss-not-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "keep ss-not-full | PrioritySampling.SAMPLER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "drop 2 ss-not-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING", - "user keep ss-not-full | PrioritySampling.USER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", - "unset ss-full | PrioritySampling.UNSET | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop ss-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "keep ss-full | PrioritySampling.SAMPLER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", - "drop 2 ss-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW ", - "user keep ss-full | PrioritySampling.USER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION " + "scenario | priority | primaryOffers | singleSpanOffers | singleSpanFull | expectedResult ", + "unset ss-not-full | PrioritySampling.UNSET | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop ss-not-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "keep ss-not-full | PrioritySampling.SAMPLER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "drop 2 ss-not-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "user keep ss-not-full | PrioritySampling.USER_KEEP | 1 | 0 | false | ENQUEUED_FOR_SERIALIZATION ", + "unset ss-full | PrioritySampling.UNSET | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop ss-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "keep ss-full | PrioritySampling.SAMPLER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION ", + "drop 2 ss-full | PrioritySampling.SAMPLER_DROP | 0 | 1 | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "user keep ss-full | PrioritySampling.USER_KEEP | 1 | 0 | true | ENQUEUED_FOR_SERIALIZATION " }) void testFastLaneStrategyWithSpanSamplingQueue( @ConvertWith(PrioritySamplingConverter.class) int priority, @@ -276,11 +276,15 @@ void testFastLaneWithActiveDroppingPolicySendToSingleSpanSampling( @SuppressWarnings("unchecked") @TableTest({ - "scenario | strategy | forceKeep | singleSpanFull | expectedResult ", - "force keep true full | FAST_LANE | true | true | ENQUEUED_FOR_SERIALIZATION ", - "force keep false full | FAST_LANE | false | true | DROPPED_BUFFER_OVERFLOW ", - "force keep true not full | FAST_LANE | true | false | ENQUEUED_FOR_SERIALIZATION ", - "force keep false not full | FAST_LANE | false | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING" + "scenario | strategy | forceKeep | singleSpanFull | expectedResult ", + "force keep true full fast lane | FAST_LANE | true | true | ENQUEUED_FOR_SERIALIZATION ", + "force keep false full fast lane | FAST_LANE | false | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "force keep true not full fast lane | FAST_LANE | true | false | ENQUEUED_FOR_SERIALIZATION ", + "force keep false not full fast lane | FAST_LANE | false | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING ", + "force keep true full ensure trace | ENSURE_TRACE | true | true | ENQUEUED_FOR_SERIALIZATION ", + "force keep false full ensure trace | ENSURE_TRACE | false | true | DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN", + "force keep true not full ensure trace | ENSURE_TRACE | true | false | ENQUEUED_FOR_SERIALIZATION ", + "force keep false not full ensure trace | ENSURE_TRACE | false | false | ENQUEUED_FOR_SINGLE_SPAN_SAMPLING " }) void testSpanSamplingDropStrategyRespectsForceKeep( Prioritization strategy, diff --git a/dd-trace-core/src/test/java/datadog/trace/common/writer/RemoteWriterLoggingTest.java b/dd-trace-core/src/test/java/datadog/trace/common/writer/RemoteWriterLoggingTest.java new file mode 100644 index 00000000000..aa8f267cc0a --- /dev/null +++ b/dd-trace-core/src/test/java/datadog/trace/common/writer/RemoteWriterLoggingTest.java @@ -0,0 +1,132 @@ +package datadog.trace.common.writer; + +import static datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult.DROPPED_BUFFER_OVERFLOW; +import static datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult.DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT; +import static datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult.DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN; +import static java.util.concurrent.TimeUnit.SECONDS; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyInt; +import static org.mockito.ArgumentMatchers.eq; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import datadog.trace.api.sampling.PrioritySampling; +import datadog.trace.common.writer.ddagent.PrioritizationStrategy.PublishResult; +import datadog.trace.core.DDCoreJavaSpecification; +import datadog.trace.core.DDSpan; +import datadog.trace.core.monitor.HealthMetrics; +import datadog.trace.core.propagation.PropagationTags; +import java.util.Collections; +import java.util.List; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +/** + * Buffer overflow is only newsworthy when a trace the tracer meant to send was lost. Overflow that + * discards an already sampled-out trace is routine and must not reach the user as a warning. + */ +class RemoteWriterLoggingTest extends DDCoreJavaSpecification { + + private Logger logger; + private Level previousLevel; + private ListAppender appender; + + private final HealthMetrics monitor = mock(HealthMetrics.class); + private final TraceProcessingWorker worker = mock(TraceProcessingWorker.class); + private final PayloadDispatcherImpl dispatcher = mock(PayloadDispatcherImpl.class); + private final DDAgentWriter writer = + new DDAgentWriter(worker, dispatcher, monitor, 1, SECONDS, false); + + @BeforeEach + void attachAppender() { + logger = (Logger) LoggerFactory.getLogger(RemoteWriter.class); + previousLevel = logger.getLevel(); + // WARN, not DEBUG: at DEBUG the writer logs the detailed message instead of the rate-limited + // warning, which is not the path a user in production sees. + logger.setLevel(Level.WARN); + appender = new ListAppender<>(); + appender.start(); + logger.addAppender(appender); + } + + @AfterEach + void detachAppender() { + logger.detachAppender(appender); + logger.setLevel(previousLevel); + writer.close(); + } + + @Test + void warnsWhenAKeptTraceIsLostToOverflow() { + write(PrioritySampling.SAMPLER_KEEP, DROPPED_BUFFER_OVERFLOW); + + assertEquals(1, appender.list.size()); + ILoggingEvent event = appender.list.get(0); + assertEquals(Level.WARN, event.getLevel()); + assertTrue( + event.getFormattedMessage().contains("kept trace"), + "the warning should say a kept trace was lost: " + event.getFormattedMessage()); + } + + @Test + void staysQuietWhenOnlyASampledOutTraceIsLostToOverflow() { + write(PrioritySampling.SAMPLER_DROP, DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT); + + assertEquals( + Collections.emptyList(), + appender.list, + "losing an already sampled-out trace must not warn the user"); + } + + @Test + void warnsWhenASingleSpanSamplingCandidateIsLostToOverflow() { + write(PrioritySampling.SAMPLER_DROP, DROPPED_BUFFER_OVERFLOW_SINGLE_SPAN); + + assertEquals(1, appender.list.size()); + ILoggingEvent event = appender.list.get(0); + assertEquals(Level.WARN, event.getLevel()); + assertTrue( + event.getFormattedMessage().contains("single span sampling"), + "the warning should say a single span sampling candidate was lost: " + + event.getFormattedMessage()); + } + + /** + * The rate limiter holds a single budget, so a flood of the benign case must not consume the + * budget that the genuine warning needs. + */ + @Test + void sampledOutOverflowDoesNotSuppressAKeptTraceWarning() { + for (int i = 0; i < 100; i++) { + write(PrioritySampling.SAMPLER_DROP, DROPPED_BUFFER_OVERFLOW_SAMPLED_OUT); + } + + write(PrioritySampling.SAMPLER_KEEP, DROPPED_BUFFER_OVERFLOW); + + assertEquals(1, appender.list.size()); + ILoggingEvent event = appender.list.get(0); + assertEquals(Level.WARN, event.getLevel()); + // The surviving warning must be the one about the kept trace, not a benign one that happened + // to claim the budget first. + assertTrue( + event.getFormattedMessage().contains("kept trace"), + "expected the kept-trace warning, got: " + event.getFormattedMessage()); + } + + private void write(byte priority, PublishResult result) { + DDSpan root = buildSpan(0L, "test.tag", "test.value", PropagationTags.factory().empty()); + root.setSamplingPriority(priority); + List trace = Collections.singletonList(root); + when(worker.publish(any(), anyInt(), eq(trace))).thenReturn(result); + + writer.write(trace); + } +}