From d4465cfd7162af35deacea034239e2e6ea48f7e1 Mon Sep 17 00:00:00 2001 From: Norbert Orzechowicz Date: Thu, 12 Feb 2026 19:41:17 +0100 Subject: [PATCH 1/2] refactor: expand logger methods allowing to pass more optional context - fixed regex rules in symfony telemetry bundle --- .../Console/ConsoleSpanSubscriber.php | 6 +- .../Twig/TracingTwigExtension.php | 6 +- .../ETL/Config/Telemetry/TelemetryContext.php | 42 +++-- .../src/Flow/Telemetry/Logger/Logger.php | 145 +++++++++++++++--- .../Unit/Logger/MemoryLoggerProviderTest.php | 70 ++++++++- 5 files changed, 226 insertions(+), 43 deletions(-) diff --git a/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Console/ConsoleSpanSubscriber.php b/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Console/ConsoleSpanSubscriber.php index 70e02e058..6197bbe42 100644 --- a/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Console/ConsoleSpanSubscriber.php +++ b/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Console/ConsoleSpanSubscriber.php @@ -102,8 +102,10 @@ public function onTerminate(ConsoleTerminateEvent $event) : void private function matchesPattern(string $command, string $pattern) : bool { - if (\str_starts_with($pattern, '/') && \str_ends_with($pattern, '/')) { - return (bool) \preg_match($pattern, $command); + $result = @\preg_match($pattern, $command); + + if ($result !== false) { + return (bool) $result; } return $command === $pattern; diff --git a/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Twig/TracingTwigExtension.php b/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Twig/TracingTwigExtension.php index a68194e9a..7b82196e8 100644 --- a/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Twig/TracingTwigExtension.php +++ b/src/bridge/symfony/telemetry-bundle/src/Flow/Bridge/Symfony/TelemetryBundle/Instrumentation/Twig/TracingTwigExtension.php @@ -121,8 +121,10 @@ private function isTemplateExcluded(string $template) : bool private function matchesPattern(string $template, string $pattern) : bool { - if (\str_starts_with($pattern, '/') && \str_ends_with($pattern, '/')) { - return (bool) \preg_match($pattern, $template); + $result = @\preg_match($pattern, $template); + + if ($result !== false) { + return (bool) $result; } return $template === $pattern; diff --git a/src/core/etl/src/Flow/ETL/Config/Telemetry/TelemetryContext.php b/src/core/etl/src/Flow/ETL/Config/Telemetry/TelemetryContext.php index fad4a428f..6690f78d2 100644 --- a/src/core/etl/src/Flow/ETL/Config/Telemetry/TelemetryContext.php +++ b/src/core/etl/src/Flow/ETL/Config/Telemetry/TelemetryContext.php @@ -69,12 +69,16 @@ public function dataFrameCompleted(FlowContext $context, array $attributes = []) return; } - $this->logger()->debug('Data frame processing completed', [ - 'dataframe_id' => $context->config->id(), - 'total_rows_processed' => $this->totalRowsProcessed, - 'memory_min_mb' => $this->memory->min()->inMb(), - 'memory_max_mb' => $this->memory->max()->inMb(), - ]); + $this->logger()->debug( + 'Data frame processing completed', + [ + 'dataframe_id' => $context->config->id(), + 'total_rows_processed' => $this->totalRowsProcessed, + 'memory_min_mb' => $this->memory->min()->inMb(), + 'memory_max_mb' => $this->memory->max()->inMb(), + ], + spanContext: $this->dataFrameSpan->context() + ); $throughput = 0.0; @@ -118,18 +122,22 @@ public function dataFrameStarted(FlowContext $context) : void { $this->dataFrameSpan = $this->tracer->span(DataFrame::class); - $this->logger()->debug('Data frame processing started', [ - 'dataframe_id' => $context->config->id(), - 'cache' => $context->cache()::class, - 'serializer' => $context->config->serializer()::class, - 'optimizers' => \array_map(static fn (Optimization $optimization) => $optimization::class, $context->config->optimizer()->optimizations()), - 'telemetry' => [ - 'trace_loading' => $this->options->traceLoading, - 'trace_transformations' => $this->options->traceTransformations, - 'collect_metrics' => $this->options->collectMetrics, + $this->logger()->debug( + 'Data frame processing started', + [ + 'dataframe_id' => $context->config->id(), + 'cache' => $context->cache()::class, + 'serializer' => $context->config->serializer()::class, + 'optimizers' => \array_map(static fn (Optimization $optimization) => $optimization::class, $context->config->optimizer()->optimizations()), + 'telemetry' => [ + 'trace_loading' => $this->options->traceLoading, + 'trace_transformations' => $this->options->traceTransformations, + 'collect_metrics' => $this->options->collectMetrics, + ], + 'fstab' => \array_map(static fn (Filesystem $filesystem) => $filesystem::class, $context->config->fstab()->filesystems()), ], - 'fstab' => \array_map(static fn (Filesystem $filesystem) => $filesystem::class, $context->config->fstab()->filesystems()), - ]); + spanContext: $this->dataFrameSpan->context() + ); if ($this->options->collectMetrics) { $this->counterProcessedRows = $this->meter->createCounter('rows.processed.total', 'Rows Processed'); diff --git a/src/lib/telemetry/src/Flow/Telemetry/Logger/Logger.php b/src/lib/telemetry/src/Flow/Telemetry/Logger/Logger.php index 8382180a6..fad6bb913 100644 --- a/src/lib/telemetry/src/Flow/Telemetry/Logger/Logger.php +++ b/src/lib/telemetry/src/Flow/Telemetry/Logger/Logger.php @@ -49,10 +49,27 @@ public function __construct( * * @param string $body The log message * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function debug(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::DEBUG, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function debug( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::DEBUG, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** @@ -62,15 +79,16 @@ public function debug(string $body, array|Attributes $attributes = []) : void * such as setting a custom timestamp or recording an exception. * * @param LogRecord $record The log record to emit + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function emit(LogRecord $record) : void + public function emit(LogRecord $record, ?SpanContext $spanContext = null) : void { $entry = new LogEntry( $record, $this->resource, $this->scope, $record->timestamp ?? $this->clock->now(), - $this->resolveSpanContext(), + $spanContext ?? $this->resolveSpanContext(), ); $this->processor->process($entry); @@ -84,10 +102,27 @@ public function emit(LogRecord $record) : void * * @param string $body The log message * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function error(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::ERROR, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function error( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::ERROR, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** @@ -98,10 +133,27 @@ public function error(string $body, array|Attributes $attributes = []) : void * * @param string $body The log message * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function fatal(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::FATAL, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function fatal( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::FATAL, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** @@ -120,10 +172,27 @@ public function flush() : bool * * @param string $body The log message * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function info(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::INFO, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function info( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::INFO, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** @@ -150,10 +219,27 @@ public function processor() : LogProcessor * * @param string $body The log message * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function trace(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::TRACE, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function trace( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::TRACE, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** @@ -163,11 +249,28 @@ public function trace(string $body, array|Attributes $attributes = []) : void * the application from functioning. * * @param string $body The log message - * @param array|bool|float|int|string>|Attributes $attributes Optional attributes + * @param Attributes|TAttributeValueMap $attributes Optional attributes + * @param null|\DateTimeImmutable $timestamp When the event occurred (defaults to current time) + * @param null|\DateTimeImmutable $observedTimestamp When the log was observed by collection + * @param null|SpanContext $spanContext Span context for trace correlation (defaults to current active span) */ - public function warn(string $body, array|Attributes $attributes = []) : void - { - $this->emit(new LogRecord(Severity::WARN, $body, $attributes instanceof Attributes ? $attributes : Attributes::create($attributes))); + public function warn( + string $body, + array|Attributes $attributes = [], + ?\DateTimeImmutable $timestamp = null, + ?\DateTimeImmutable $observedTimestamp = null, + ?SpanContext $spanContext = null, + ) : void { + $this->emit( + new LogRecord( + Severity::WARN, + $body, + $attributes instanceof Attributes ? $attributes : Attributes::create($attributes), + $timestamp, + $observedTimestamp, + ), + $spanContext, + ); } /** diff --git a/src/lib/telemetry/tests/Flow/Telemetry/Tests/Unit/Logger/MemoryLoggerProviderTest.php b/src/lib/telemetry/tests/Flow/Telemetry/Tests/Unit/Logger/MemoryLoggerProviderTest.php index 371713a13..3513254ed 100644 --- a/src/lib/telemetry/tests/Flow/Telemetry/Tests/Unit/Logger/MemoryLoggerProviderTest.php +++ b/src/lib/telemetry/tests/Flow/Telemetry/Tests/Unit/Logger/MemoryLoggerProviderTest.php @@ -5,11 +5,12 @@ namespace Flow\Telemetry\Tests\Unit\Logger; use Flow\Telemetry\{Attributes, Resource}; -use Flow\Telemetry\Context\MemoryContextStorage; +use Flow\Telemetry\Context\{MemoryContextStorage, SpanId, TraceId}; use Flow\Telemetry\Logger\{Logger, LoggerProvider, Severity}; use Flow\Telemetry\Provider\Memory\MemoryLogProcessor; use Flow\Telemetry\Provider\Void\VoidLogExporter; use Flow\Telemetry\Tests\Mother\{ClockMother, ResourceMother}; +use Flow\Telemetry\Tracer\SpanContext; use PHPUnit\Framework\TestCase; final class MemoryLoggerProviderTest extends TestCase @@ -43,6 +44,73 @@ public function test_logger_accepts_attributes_object() : void self::assertSame('value', $processor->entries()[0]->record->attributes->normalize()['key']); } + public function test_logger_accepts_custom_observed_timestamp() : void + { + $processor = $this->createProcessor(); + $provider = new LoggerProvider($processor, ClockMother::frozen(), new MemoryContextStorage()); + $logger = $provider->logger($this->resource, 'service', '1.0'); + $observedTimestamp = new \DateTimeImmutable('2024-01-15 10:35:00'); + + $logger->info('message with observed timestamp', [], null, $observedTimestamp); + + self::assertCount(1, $processor->entries()); + self::assertEquals($observedTimestamp, $processor->entries()[0]->record->observedTimestamp); + } + + public function test_logger_accepts_custom_span_context() : void + { + $processor = $this->createProcessor(); + $provider = new LoggerProvider($processor, ClockMother::frozen(), new MemoryContextStorage()); + $logger = $provider->logger($this->resource, 'service', '1.0'); + $customSpanContext = SpanContext::create( + TraceId::generate(), + SpanId::generate(), + ); + + $logger->info('message with custom span context', [], null, null, $customSpanContext); + + self::assertCount(1, $processor->entries()); + self::assertSame($customSpanContext, $processor->entries()[0]->spanContext); + } + + public function test_logger_accepts_custom_timestamp() : void + { + $processor = $this->createProcessor(); + $provider = new LoggerProvider($processor, ClockMother::frozen(), new MemoryContextStorage()); + $logger = $provider->logger($this->resource, 'service', '1.0'); + $customTimestamp = new \DateTimeImmutable('2024-01-15 10:30:00'); + + $logger->info('message with custom timestamp', [], $customTimestamp); + + self::assertCount(1, $processor->entries()); + self::assertEquals($customTimestamp, $processor->entries()[0]->timestamp); + } + + public function test_logger_passes_all_custom_parameters_for_all_severity_levels() : void + { + $processor = $this->createProcessor(); + $provider = new LoggerProvider($processor, ClockMother::frozen(), new MemoryContextStorage()); + $logger = $provider->logger($this->resource, 'service', '1.0'); + $timestamp = new \DateTimeImmutable('2024-01-15 10:30:00'); + $observedTimestamp = new \DateTimeImmutable('2024-01-15 10:35:00'); + $spanContext = SpanContext::create(TraceId::generate(), SpanId::generate()); + + $logger->trace('trace msg', [], $timestamp, $observedTimestamp, $spanContext); + $logger->debug('debug msg', [], $timestamp, $observedTimestamp, $spanContext); + $logger->info('info msg', [], $timestamp, $observedTimestamp, $spanContext); + $logger->warn('warn msg', [], $timestamp, $observedTimestamp, $spanContext); + $logger->error('error msg', [], $timestamp, $observedTimestamp, $spanContext); + $logger->fatal('fatal msg', [], $timestamp, $observedTimestamp, $spanContext); + + self::assertCount(6, $processor->entries()); + + foreach ($processor->entries() as $entry) { + self::assertEquals($timestamp, $entry->timestamp); + self::assertEquals($observedTimestamp, $entry->record->observedTimestamp); + self::assertSame($spanContext, $entry->spanContext); + } + } + public function test_logger_returns_logger_instance() : void { $provider = new LoggerProvider($this->createProcessor(), ClockMother::frozen(), new MemoryContextStorage()); From 4fe2df303b33ed63fa01bedae2c44219a8004b43 Mon Sep 17 00:00:00 2001 From: Norbert Orzechowicz Date: Thu, 12 Feb 2026 20:16:37 +0100 Subject: [PATCH 2/2] fix: failing symfony telemetry bundle tests --- .../Console/ConsoleSpanSubscriberTest.php | 12 ++++++------ .../Tests/Integration/KernelTestCase.php | 12 ++++++++++++ .../Doctrine/DBAL/TracingConnectionTest.php | 3 ++- 3 files changed, 20 insertions(+), 7 deletions(-) diff --git a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/Instrumentation/Console/ConsoleSpanSubscriberTest.php b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/Instrumentation/Console/ConsoleSpanSubscriberTest.php index 3d67124b0..6e7b32e48 100644 --- a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/Instrumentation/Console/ConsoleSpanSubscriberTest.php +++ b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/Instrumentation/Console/ConsoleSpanSubscriberTest.php @@ -57,7 +57,7 @@ public function test_does_not_trace_when_disabled() : void ]); $application = new Application($kernel); - $application->add(new TestCommand()); + $this->addCommand($application, new TestCommand()); $application->setAutoExit(false); $application->setCatchExceptions(false); @@ -108,7 +108,7 @@ public function test_excludes_command_with_exact_match() : void ]); $application = new Application($kernel); - $application->add(new TestCommand()); + $this->addCommand($application, new TestCommand()); $application->setAutoExit(false); $application->setCatchExceptions(false); @@ -159,8 +159,8 @@ public function test_excludes_command_with_regex_pattern() : void ]); $application = new Application($kernel); - $application->add(new TestCommand()); - $application->add(new FailingCommand()); + $this->addCommand($application, new TestCommand()); + $this->addCommand($application, new FailingCommand()); $application->setAutoExit(false); $application->setCatchExceptions(false); @@ -211,7 +211,7 @@ public function test_traces_failing_console_command() : void ]); $application = new Application($kernel); - $application->add(new FailingCommand()); + $this->addCommand($application, new FailingCommand()); $application->setAutoExit(false); $application->setCatchExceptions(false); @@ -271,7 +271,7 @@ public function test_traces_successful_console_command() : void ]); $application = new Application($kernel); - $application->add(new TestCommand()); + $this->addCommand($application, new TestCommand()); $application->setAutoExit(false); $application->setCatchExceptions(false); diff --git a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/KernelTestCase.php b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/KernelTestCase.php index ae57847bb..1225d569a 100644 --- a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/KernelTestCase.php +++ b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Integration/KernelTestCase.php @@ -7,6 +7,8 @@ use Flow\Bridge\Symfony\TelemetryBundle\Tests\Context\SymfonyContext; use Flow\Bridge\Symfony\TelemetryBundle\Tests\Fixtures\TestKernel; use PHPUnit\Framework\TestCase; +use Symfony\Component\Console\Application; +use Symfony\Component\Console\Command\Command; use Symfony\Component\DependencyInjection\ContainerInterface; abstract class KernelTestCase extends TestCase @@ -23,6 +25,16 @@ protected function tearDown() : void $this->context->shutdown(); } + protected function addCommand(Application $application, Command $command) : void + { + /** @phpstan-ignore function.alreadyNarrowedType */ + if (\method_exists($application, 'addCommand')) { + $application->addCommand($command); + } else { + $application->add($command); + } + } + /** * @param array{config?: callable(TestKernel): void} $options */ diff --git a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Unit/Instrumentation/Doctrine/DBAL/TracingConnectionTest.php b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Unit/Instrumentation/Doctrine/DBAL/TracingConnectionTest.php index 27cb15c06..eb5e32da0 100644 --- a/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Unit/Instrumentation/Doctrine/DBAL/TracingConnectionTest.php +++ b/src/bridge/symfony/telemetry-bundle/tests/Flow/Bridge/Symfony/TelemetryBundle/Tests/Unit/Instrumentation/Doctrine/DBAL/TracingConnectionTest.php @@ -328,7 +328,8 @@ public function rowCount() : int }; } - public function quote(string $value) : string + /** @phpstan-ignore missingType.parameter, missingType.parameter */ + public function quote($value, $type = ParameterType::STRING) : string { return "'{$value}'"; }