feat(laravel-auto-instrumentation): use logger provider in logwatcher (…

…#286) * feat(laravel-auto-instrumentation): use logger provider in logwatcher * style: correctly order import statements * test: update test offsets for logging storage
open-telemetry · Aug 29, 2024 · b10cb8d · b10cb8d
1 parent 662e25a
commit b10cb8d
Show file tree

Hide file tree

Showing 5 changed files with 71 additions and 36 deletions.
diff --git a/src/Instrumentation/Laravel/src/Hooks/Illuminate/Foundation/Application.php b/src/Instrumentation/Laravel/src/Hooks/Illuminate/Foundation/Application.php
@@ -30,7 +30,7 @@ public function instrument(): void
                 $this->registerWatchers($application, new CacheWatcher());
                 $this->registerWatchers($application, new ClientRequestWatcher($this->instrumentation));
                 $this->registerWatchers($application, new ExceptionWatcher());
-                $this->registerWatchers($application, new LogWatcher());
+                $this->registerWatchers($application, new LogWatcher($this->instrumentation));
                 $this->registerWatchers($application, new QueryWatcher($this->instrumentation));
             },
         );

diff --git a/src/Instrumentation/Laravel/src/Watchers/LogWatcher.php b/src/Instrumentation/Laravel/src/Watchers/LogWatcher.php
@@ -6,11 +6,17 @@
 
 use Illuminate\Contracts\Foundation\Application;
 use Illuminate\Log\Events\MessageLogged;
-use OpenTelemetry\API\Trace\Span;
-use OpenTelemetry\Context\Context;
+use OpenTelemetry\API\Instrumentation\CachedInstrumentation;
+use OpenTelemetry\API\Logs\LogRecord;
+use OpenTelemetry\API\Logs\Map\Psr3;
 
 class LogWatcher extends Watcher
 {
+    public function __construct(
+        private CachedInstrumentation $instrumentation,
+    ) {
+    }
+
     /** @psalm-suppress UndefinedInterfaceMethod */
     public function register(Application $app): void
     {
@@ -24,18 +30,16 @@ public function register(Application $app): void
     public function recordLog(MessageLogged $log): void
     {
         $attributes = [
-            'level' => $log->level,
+            'context' => json_encode(array_filter($log->context)),
         ];
 
-        $attributes['context'] = json_encode(array_filter($log->context));
+        $logger = $this->instrumentation->logger();
 
-        $message = $log->message;
+        $record = (new LogRecord($log->message))
+            ->setSeverityText($log->level)
+            ->setSeverityNumber(Psr3::severityNumber($log->level))
+            ->setAttributes($attributes);
 
-        $scope = Context::storage()->scope();
-        if (!$scope) {
-            return;
-        }
-        $span = Span::fromContext($scope->context());
-        $span->addEvent($message, $attributes);
+        $logger->emit($record);
     }
 }
diff --git a/src/Instrumentation/Laravel/tests/Integration/LaravelInstrumentationTest.php b/src/Instrumentation/Laravel/tests/Integration/LaravelInstrumentationTest.php
@@ -34,7 +34,7 @@ public function test_cache_log_db(): void
         $this->router()->get('/hello', function () {
             $text = 'Hello Cruel World';
             cache()->forever('opentelemetry', 'opentelemetry');
-            Log::info('Log info');
+            Log::info('Log info', ['test' => true]);
             cache()->get('opentelemetry.io', 'php');
             cache()->get('opentelemetry', 'php');
             cache()->forget('opentelemetry');
@@ -46,23 +46,30 @@ public function test_cache_log_db(): void
         $this->assertCount(0, $this->storage);
         $response = $this->call('GET', '/hello');
         $this->assertEquals(200, $response->status());
-        $this->assertCount(2, $this->storage);
-        $span = $this->storage[1];
+        $this->assertCount(3, $this->storage);
+        $span = $this->storage[2];
         $this->assertSame('GET /hello', $span->getName());
         $this->assertSame('http://localhost/hello', $span->getAttributes()->get(TraceAttributes::URL_FULL));
-        $this->assertCount(5, $span->getEvents());
+        $this->assertCount(4, $span->getEvents());
         $this->assertSame('cache set', $span->getEvents()[0]->getName());
-        $this->assertSame('Log info', $span->getEvents()[1]->getName());
-        $this->assertSame('cache miss', $span->getEvents()[2]->getName());
-        $this->assertSame('cache hit', $span->getEvents()[3]->getName());
-        $this->assertSame('cache forget', $span->getEvents()[4]->getName());
+        $this->assertSame('cache miss', $span->getEvents()[1]->getName());
+        $this->assertSame('cache hit', $span->getEvents()[2]->getName());
+        $this->assertSame('cache forget', $span->getEvents()[3]->getName());
 
-        $span = $this->storage[0];
+        $span = $this->storage[1];
         $this->assertSame('sql SELECT', $span->getName());
         $this->assertSame('SELECT', $span->getAttributes()->get('db.operation'));
         $this->assertSame(':memory:', $span->getAttributes()->get('db.name'));
         $this->assertSame('select 1', $span->getAttributes()->get('db.statement'));
         $this->assertSame('sqlite', $span->getAttributes()->get('db.system'));
+
+        /** @var \OpenTelemetry\SDK\Logs\ReadWriteLogRecord $logRecord */
+        $logRecord = $this->storage[0];
+        $this->assertSame('Log info', $logRecord->getBody());
+        $this->assertSame('info', $logRecord->getSeverityText());
+        $this->assertSame(9, $logRecord->getSeverityNumber());
+        $this->assertArrayHasKey('context', $logRecord->getAttributes()->toArray());
+        $this->assertSame(json_encode(['test' => true]), $logRecord->getAttributes()->toArray()['context']);
     }
 
     public function test_low_cardinality_route_span_name(): void

diff --git a/src/Instrumentation/Laravel/tests/Integration/Queue/QueueTest.php b/src/Instrumentation/Laravel/tests/Integration/Queue/QueueTest.php
@@ -38,11 +38,15 @@ public function test_it_handles_pushing_to_a_queue(): void
             $logger->info('Logged from closure');
         });
 
-        $this->assertEquals('sync process', $this->storage[0]->getName());
-        $this->assertEquals('Task: A', $this->storage[0]->getEvents()[0]->getName());
-
+        /** @var \OpenTelemetry\SDK\Logs\ReadWriteLogRecord $logRecord0 */
+        $logRecord0 = $this->storage[0];
+        $this->assertEquals('Task: A', $logRecord0->getBody());
         $this->assertEquals('sync process', $this->storage[1]->getName());
-        $this->assertEquals('Logged from closure', $this->storage[1]->getEvents()[0]->getName());
+
+        /** @var \OpenTelemetry\SDK\Logs\ReadWriteLogRecord $logRecord2 */
+        $logRecord2 = $this->storage[2];
+        $this->assertEquals('Logged from closure', $logRecord2->getBody());
+        $this->assertEquals('sync process', $this->storage[3]->getName());
     }
 
     public function test_it_can_push_a_message_with_a_delay(): void
@@ -51,19 +55,19 @@ public function test_it_can_push_a_message_with_a_delay(): void
         $this->queue->later(new DateInterval('PT10M'), new DummyJob('DateInterval'));
         $this->queue->later(new DateTimeImmutable('2024-04-15 22:29:00.123Z'), new DummyJob('DateTime'));
 
-        $this->assertEquals('sync create', $this->storage[1]->getName());
+        $this->assertEquals('sync create', $this->storage[2]->getName());
         $this->assertIsInt(
-            $this->storage[1]->getAttributes()->get('messaging.message.delivery_timestamp'),
+            $this->storage[2]->getAttributes()->get('messaging.message.delivery_timestamp'),
         );
 
-        $this->assertEquals('sync create', $this->storage[3]->getName());
+        $this->assertEquals('sync create', $this->storage[5]->getName());
         $this->assertIsInt(
-            $this->storage[3]->getAttributes()->get('messaging.message.delivery_timestamp'),
+            $this->storage[5]->getAttributes()->get('messaging.message.delivery_timestamp'),
         );
 
-        $this->assertEquals('sync create', $this->storage[5]->getName());
+        $this->assertEquals('sync create', $this->storage[8]->getName());
         $this->assertIsInt(
-            $this->storage[5]->getAttributes()->get('messaging.message.delivery_timestamp'),
+            $this->storage[8]->getAttributes()->get('messaging.message.delivery_timestamp'),
         );
     }
 
@@ -141,9 +145,14 @@ public function test_it_drops_empty_receives(): void
         }
 
         /** @psalm-suppress PossiblyInvalidMethodCall */
-        $this->assertEquals(102, $this->storage->count());
+        $this->assertEquals(204, $this->storage->count());
+
+        /** @var \OpenTelemetry\SDK\Logs\ReadWriteLogRecord $logRecord100 */
+        $logRecord100 = $this->storage[100];
+        $this->assertEquals('Task: 500', $logRecord100->getBody());
 
-        $this->assertEquals('Task: 500', $this->storage[50]->getEvents()[0]->getName());
-        $this->assertEquals('Task: More work', $this->storage[100]->getEvents()[0]->getName());
+        /** @var \OpenTelemetry\SDK\Logs\ReadWriteLogRecord $logRecord200 */
+        $logRecord200 = $this->storage[200];
+        $this->assertEquals('Task: More work', $logRecord200->getBody());
     }
 }
diff --git a/src/Instrumentation/Laravel/tests/Integration/TestCase.php b/src/Instrumentation/Laravel/tests/Integration/TestCase.php
@@ -7,8 +7,13 @@
 use ArrayObject;
 use OpenTelemetry\API\Instrumentation\Configurator;
 use OpenTelemetry\Context\ScopeInterface;
+use OpenTelemetry\SDK\Common\Attribute\Attributes;
+use OpenTelemetry\SDK\Common\Instrumentation\InstrumentationScopeFactory;
+use OpenTelemetry\SDK\Logs\Exporter\InMemoryExporter as LogInMemoryExporter;
+use OpenTelemetry\SDK\Logs\LoggerProvider;
+use OpenTelemetry\SDK\Logs\Processor\SimpleLogRecordProcessor;
 use OpenTelemetry\SDK\Trace\ImmutableSpan;
-use OpenTelemetry\SDK\Trace\SpanExporter\InMemoryExporter;
+use OpenTelemetry\SDK\Trace\SpanExporter\InMemoryExporter as SpanInMemoryExporter;
 use OpenTelemetry\SDK\Trace\SpanProcessor\SimpleSpanProcessor;
 use OpenTelemetry\SDK\Trace\TracerProvider;
 use Orchestra\Testbench\TestCase as BaseTestCase;
@@ -18,7 +23,9 @@ abstract class TestCase extends BaseTestCase
     protected ScopeInterface $scope;
     /** @var ArrayObject|ImmutableSpan[] $storage */
     protected ArrayObject $storage;
+    protected ArrayObject $loggerStorage;
     protected TracerProvider $tracerProvider;
+    protected LoggerProvider $loggerProvider;
 
     public function setUp(): void
     {
@@ -27,12 +34,20 @@ public function setUp(): void
         $this->storage = new ArrayObject();
         $this->tracerProvider = new TracerProvider(
             new SimpleSpanProcessor(
-                new InMemoryExporter($this->storage),
+                new SpanInMemoryExporter($this->storage),
             ),
         );
 
+        $this->loggerProvider = new LoggerProvider(
+            new SimpleLogRecordProcessor(
+                new LogInMemoryExporter($this->storage),
+            ),
+            new InstrumentationScopeFactory(Attributes::factory())
+        );
+
         $this->scope = Configurator::create()
             ->withTracerProvider($this->tracerProvider)
+            ->withLoggerProvider($this->loggerProvider)
             ->activate();
     }