From b10cb8d4ccab63bd8c0f7065eea2f4ca0b66f612 Mon Sep 17 00:00:00 2001 From: Hendrik Heil Date: Fri, 30 Aug 2024 00:51:18 +0200 Subject: [PATCH] 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 --- .../Illuminate/Foundation/Application.php | 2 +- .../Laravel/src/Watchers/LogWatcher.php | 26 ++++++++------ .../LaravelInstrumentationTest.php | 25 ++++++++----- .../tests/Integration/Queue/QueueTest.php | 35 ++++++++++++------- .../Laravel/tests/Integration/TestCase.php | 19 ++++++++-- 5 files changed, 71 insertions(+), 36 deletions(-) diff --git a/src/Instrumentation/Laravel/src/Hooks/Illuminate/Foundation/Application.php b/src/Instrumentation/Laravel/src/Hooks/Illuminate/Foundation/Application.php index f76b2986..ebae628c 100644 --- 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 index f887da83..a5163c67 100644 --- 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 index 5dd520bb..c5096ff3 100644 --- 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 index 5ad620e9..1d902e0b 100644 --- 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 index 48be7463..56c1abbb 100644 --- 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(); }