log discarded span+log attributes (open-telemetry#1336)

The SDK should log a warning once if there are any dropped span attributes, links, link attributes, events or event attributes. The SDK should log a warning once if there are any dropped LogRecord attributes.
brettmc · Jun 26, 2024 · b6f9afb · b6f9afb
1 parent a90f18c
commit b6f9afb
Show file tree

Hide file tree

Showing 8 changed files with 132 additions and 2 deletions.
diff --git a/.phan/config.php b/.phan/config.php
@@ -375,7 +375,6 @@
         'vendor/guzzlehttp',
         'vendor/psr',
         'vendor/php-http',
-        'vendor/phan/phan/src/Phan',
         'vendor/phpunit/phpunit/src',
         'vendor/google/protobuf/src',
         'vendor/ramsey/uuid/src',

diff --git a/src/SDK/Logs/LogRecordLimits.php b/src/SDK/Logs/LogRecordLimits.php
@@ -12,7 +12,7 @@
 class LogRecordLimits
 {
     /**
-     * @internal Use {@see SpanLimitsBuilder} to create {@see SpanLimits} instance.
+     * @internal Use {@see LogRecordLimitsBuilder} to create {@see LogRecordLimits} instance.
      */
     public function __construct(private readonly AttributesFactoryInterface $attributesFactory)
     {

diff --git a/src/SDK/Logs/Logger.php b/src/SDK/Logs/Logger.php
@@ -4,6 +4,7 @@
 
 namespace OpenTelemetry\SDK\Logs;
 
+use OpenTelemetry\API\Behavior\LogsMessagesTrait;
 use OpenTelemetry\API\Logs\LoggerInterface;
 use OpenTelemetry\API\Logs\LogRecord;
 use OpenTelemetry\SDK\Common\Instrumentation\InstrumentationScopeInterface;
@@ -16,6 +17,8 @@
  */
 class Logger implements LoggerInterface
 {
+    use LogsMessagesTrait;
+
     /**
      * @internal
      */
@@ -33,5 +36,10 @@ public function emit(LogRecord $logRecord): void
             $readWriteLogRecord,
             $readWriteLogRecord->getContext(),
         );
+        if ($readWriteLogRecord->getAttributes()->getDroppedAttributesCount()) {
+            self::logWarning('Dropped log attributes', [
+                'attributes' => $readWriteLogRecord->getAttributes()->getDroppedAttributesCount(),
+            ]);
+        }
     }
 }
diff --git a/src/SDK/Trace/Span.php b/src/SDK/Trace/Span.php
@@ -4,6 +4,7 @@
 
 namespace OpenTelemetry\SDK\Trace;
 
+use OpenTelemetry\API\Behavior\LogsMessagesTrait;
 use OpenTelemetry\API\Common\Time\Clock;
 use OpenTelemetry\API\Trace as API;
 use OpenTelemetry\API\Trace\SpanContextInterface;
@@ -17,6 +18,7 @@
 
 final class Span extends API\Span implements ReadWriteSpanInterface
 {
+    use LogsMessagesTrait;
 
     /** @var list<EventInterface> */
     private array $events = [];
@@ -252,6 +254,8 @@ public function end(int $endEpochNanos = null): void
         $this->endEpochNanos = $endEpochNanos ?? Clock::getDefault()->now();
         $this->hasEnded = true;
 
+        $this->checkForDroppedElements();
+
         $this->spanProcessor->onEnd($this);
     }
 
@@ -329,4 +333,34 @@ public function getResource(): ResourceInfo
     {
         return $this->resource;
     }
+
+    private function checkForDroppedElements(): void
+    {
+        $spanData = $this->toSpanData(); //@todo could be optimized to reduce overhead of multiple calls
+        $droppedLinkAttributes = 0;
+        $droppedEventAttributes = 0;
+        array_map(function (EventInterface $event) use (&$droppedEventAttributes) {
+            $droppedEventAttributes += $event->getAttributes()->getDroppedAttributesCount();
+        }, $spanData->getEvents());
+        array_map(function (LinkInterface $link) use (&$droppedLinkAttributes) {
+            $droppedLinkAttributes += $link->getAttributes()->getDroppedAttributesCount();
+        }, $spanData->getLinks());
+        if (
+            $spanData->getTotalDroppedLinks() ||
+            $spanData->getTotalDroppedEvents() ||
+            $spanData->getAttributes()->getDroppedAttributesCount() ||
+            $droppedEventAttributes ||
+            $droppedLinkAttributes
+        ) {
+            self::logWarning('Dropped span attributes, links or events', [
+                'trace_id' => $spanData->getTraceId(),
+                'span_id' => $spanData->getSpanId(),
+                'attributes' => $spanData->getAttributes()->getDroppedAttributesCount(),
+                'links' => $spanData->getTotalDroppedLinks(),
+                'link_attributes' => $droppedLinkAttributes,
+                'events' => $spanData->getTotalDroppedEvents(),
+                'event_attributes' => $droppedEventAttributes,
+            ]);
+        }
+    }
 }
diff --git a/tests/Integration/SDK/SpanBuilderTest.php b/tests/Integration/SDK/SpanBuilderTest.php
@@ -7,6 +7,7 @@
 use Mockery;
 use Mockery\Adapter\Phpunit\MockeryTestCase;
 use Mockery\MockInterface;
+use OpenTelemetry\API\Behavior\Internal\Logging;
 use OpenTelemetry\API\Trace as API;
 use OpenTelemetry\API\Trace\SpanContext;
 use OpenTelemetry\API\Trace\SpanContextValidator;
@@ -96,6 +97,7 @@ public function test_add_link_invalid(): void
 
     public function test_add_link_dropping_links(): void
     {
+        Logging::disable();
         $maxNumberOfLinks = 8;
         $tracerProvider = new TracerProvider([], null, null, (new SpanLimitsBuilder())->setLinkCountLimit($maxNumberOfLinks)->build());
         $spanBuilder = $tracerProvider

diff --git a/tests/Integration/SDK/TracerTest.php b/tests/Integration/SDK/TracerTest.php
@@ -4,6 +4,7 @@
 
 namespace OpenTelemetry\Tests\Integration\SDK;
 
+use OpenTelemetry\API\Behavior\Internal\Logging;
 use OpenTelemetry\API\Trace as API;
 use OpenTelemetry\API\Trace\NonRecordingSpan;
 use OpenTelemetry\API\Trace\SpanContext;
@@ -113,6 +114,7 @@ public function test_factory_returns_noop_tracer_when_sdk_disabled(): void
 
     public function test_general_identity_attributes_are_dropped_by_default(): void
     {
+        Logging::disable();
         $exporter = new InMemoryExporter();
         $tracerProvider = new TracerProvider(new SimpleSpanProcessor($exporter));
         $tracer = $tracerProvider->getTracer('test');

diff --git a/tests/Unit/SDK/Logs/LoggerTest.php b/tests/Unit/SDK/Logs/LoggerTest.php
@@ -4,15 +4,19 @@
 
 namespace OpenTelemetry\Tests\Unit\SDK\Logs;
 
+use OpenTelemetry\API\Behavior\Internal\Logging;
+use OpenTelemetry\API\Behavior\Internal\LogWriter\LogWriterInterface;
 use OpenTelemetry\API\Logs\LogRecord;
 use OpenTelemetry\Context\ContextInterface;
 use OpenTelemetry\SDK\Common\Attribute\Attributes;
 use OpenTelemetry\SDK\Common\Instrumentation\InstrumentationScope;
 use OpenTelemetry\SDK\Logs\Logger;
 use OpenTelemetry\SDK\Logs\LoggerSharedState;
+use OpenTelemetry\SDK\Logs\LogRecordLimitsBuilder;
 use OpenTelemetry\SDK\Logs\LogRecordProcessorInterface;
 use OpenTelemetry\SDK\Logs\ReadWriteLogRecord;
 use PHPUnit\Framework\Attributes\CoversClass;
+use PHPUnit\Framework\MockObject\MockObject;
 use PHPUnit\Framework\TestCase;
 
 /**
@@ -21,16 +25,28 @@
 #[CoversClass(Logger::class)]
 class LoggerTest extends TestCase
 {
+    /** @var LogWriterInterface&MockObject $logWriter */
+    private LogWriterInterface $logWriter;
     private LoggerSharedState $sharedState;
     private LogRecordProcessorInterface $processor;
     private InstrumentationScope $scope;
 
     public function setUp(): void
     {
+        $limits = (new LogRecordLimitsBuilder())->setAttributeCountLimit(1)->build();
         $this->sharedState = $this->createMock(LoggerSharedState::class);
+        $this->sharedState->method('getLogRecordLimits')->willReturn($limits);
         $this->processor = $this->createMock(LogRecordProcessorInterface::class);
         $this->sharedState->method('getProcessor')->willReturn($this->processor);
         $this->scope = new InstrumentationScope('foo', '1.0', 'schema.url', Attributes::create([])); //final
+
+        $this->logWriter = $this->createMock(LogWriterInterface::class);
+        Logging::setLogWriter($this->logWriter);
+    }
+
+    public function tearDown(): void
+    {
+        Logging::reset();
     }
 
     public function test_log_record(): void
@@ -66,4 +82,31 @@ public function test_sets_observed_timestamp_on_emit(): void
 
         $logger->emit($record);
     }
+
+    public function test_logs_dropped_attributes(): void
+    {
+        $this->logWriter
+            ->expects($this->once())
+            ->method('write')
+            ->with(
+                $this->equalTo('warning'),
+                $this->stringContains('Dropped'),
+                $this->callback(function (array $context): bool {
+                    $this->assertArrayHasKey('attributes', $context);
+                    $this->assertSame(2, $context['attributes']);
+
+                    return true;
+                }),
+            );
+        $logger = new Logger($this->sharedState, $this->scope);
+        $record = new LogRecord();
+        //limit is 1
+        $record->setAttributes([
+            'one' => 'attr_one',
+            'two' => 'attr_two',
+            'three' => 'attr_three',
+        ]);
+
+        $logger->emit($record);
+    }
 }
diff --git a/tests/Unit/SDK/Trace/SpanTest.php b/tests/Unit/SDK/Trace/SpanTest.php
@@ -48,6 +48,8 @@
 #[CoversClass(Span::class)]
 class SpanTest extends MockeryTestCase
 {
+    private const TRACE_ID = 'e4a8d4e0d75c0702200af2882cb16c6b';
+    private const SPAN_ID = '46701247e52c2d1b';
     private const SPAN_NAME = 'test_span';
     private const NEW_SPAN_NAME = 'new_test_span';
     private const START_EPOCH = 1000123789654;
@@ -655,6 +657,7 @@ public function test_attribute_length(): void
     public function test_dropping_attributes(): void
     {
         $maxNumberOfAttributes = 8;
+        $this->expectDropped(8, 0, 0);
         $span = $this->createTestSpan(API\SpanKind::KIND_INTERNAL, (new SpanLimitsBuilder())->setAttributeCountLimit($maxNumberOfAttributes)->build());
 
         foreach (range(1, $maxNumberOfAttributes * 2) as $idx) {
@@ -676,6 +679,7 @@ public function test_dropping_attributes(): void
     public function test_dropping_attributes_provided_via_span_builder(): void
     {
         $maxNumberOfAttributes = 8;
+        $this->expectDropped(8, 0, 0);
 
         $attributesBuilder = Attributes::factory()->builder();
 
@@ -704,6 +708,7 @@ public function test_dropping_attributes_provided_via_span_builder(): void
 
     public function test_dropping_events(): void
     {
+        $this->expectDropped(0, 8, 0);
         $maxNumberOfEvents = 8;
         $span = $this->createTestSpan(API\SpanKind::KIND_INTERNAL, (new SpanLimitsBuilder())->setEventCountLimit($maxNumberOfEvents)->build());
 
@@ -719,6 +724,26 @@ public function test_dropping_events(): void
         $span->end();
     }
 
+    public function test_dropping_links(): void
+    {
+        $maxNumberOfLinks = 8;
+        $expectedDroppedLinks = 9; //test span contains one link by default
+        $this->expectDropped(0, 0, $expectedDroppedLinks);
+        $span = $this->createTestSpan(API\SpanKind::KIND_INTERNAL, (new SpanLimitsBuilder())->setLinkCountLimit($maxNumberOfLinks)->build());
+        $ctx = SpanContext::create(self::TRACE_ID, self::SPAN_ID);
+
+        foreach (range(1, $maxNumberOfLinks * 2) as $_idx) {
+            $span->addLink($ctx);
+            $this->testClock->advanceSeconds();
+        }
+
+        $spanData = $span->toSpanData();
+        $this->assertCount($maxNumberOfLinks, $spanData->getLinks());
+        $this->assertSame($expectedDroppedLinks, $spanData->getTotalDroppedLinks());
+
+        $span->end();
+    }
+
     // endregion SDK
     #[Group('trace-compliance')]
     public function test_set_attributes_merges_attributes(): void
@@ -915,4 +940,21 @@ private function assertSpanData(
         $this->assertSame($hasEnded, $spanData->hasEnded());
         $this->assertEquals($attributes, $spanData->getAttributes());
     }
+
+    private function expectDropped(int $attributes, int $events, int $links): void
+    {
+        $this->logWriter->expects($this->atLeastOnce())->method('write')->with(
+            $this->anything(),
+            $this->stringContains('Dropped span attributes'),
+            $this->callback(function (array $context) use ($attributes, $events, $links) {
+                $this->assertSame($context['attributes'], $attributes);
+                $this->assertSame($context['events'], $events);
+                $this->assertSame($context['links'], $links);
+                $this->assertNotNull($context['trace_id']);
+                $this->assertNotNull($context['span_id']);
+
+                return true;
+            }),
+        );
+    }
 }