diff --git a/CHANGELOG.md b/CHANGELOG.md index d598cce..340b4b3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ Latest ## Fixes * [#229](https://github.com/cleverage/ui-process-bundle/issues/229) Login throttling of the `main` firewall (#207, #222): the requests of the HTTP API (`HttpProcessExecutionAuthenticator`) are no longer counted, on every firewall with a login throttling (`LoginThrottlingPass` decorates its limiter, the firewall settings still apply to the login form): failed logins blocked a valid API token, and invalid tokens blocked the login form of the IP address. `login_throttling: false` in the application `main` firewall disables it (it was enabled again by the bundle). With `framework.rate_limiter: false`, an explicit error tells how to fix the configuration instead of "Parent definition "limiter" does not exist". `HttpProcessExecutionAuthenticator::onAuthenticationFailure()` answers the message key of the exception, instead of an empty message when there were too many attempts. Update documentation, add tests. +* [#230](https://github.com/cleverage/ui-process-bundle/issues/230) `DoctrineProcessHandler`, `LogRecord`: a log record with an invalid UTF-8 sequence in its message or its context (e.g. a Latin-1 file imported), or with a message longer than the column in code points (`LogRecord` truncated it to 512 graphemes: emojis, combining marks), no longer makes the insertion of the logs in database fail: the invalid sequences are replaced (and the NUL characters of the message removed) and the message is truncated to 512 code points. When the insertion of the log records fails anyway, they (up to 500) are dropped and the failure is logged on the `cleverage_process` channel, instead of making the process fail (on the 500th record, even with `error_strategy: skip`) or preventing the status of its execution from being saved at its end (left `started`, the command exiting with `1`); a failure of a flush also writing pending changes of the process tasks (the entity manager is shared) is not caught, as before. Update documentation, add tests. v3.4 ------ diff --git a/config/services/monolog_handler.yaml b/config/services/monolog_handler.yaml index c5708a8..a44549d 100644 --- a/config/services/monolog_handler.yaml +++ b/config/services/monolog_handler.yaml @@ -5,8 +5,10 @@ services: calls: - [ setEntityManager, [ '@doctrine.orm.entity_manager' ] ] - [ setProcessExecutionManager, [ '@cleverage_ui_process.manager.process_execution' ] ] + - [ setLogger, [ '@?logger' ] ] tags: - { name: kernel.reset, method: reset } + - { name: 'monolog.logger', channel: 'cleverage_process' } CleverAge\UiProcessBundle\Monolog\Handler\DoctrineProcessHandler: alias: cleverage_ui_process.monolog_handler.doctrine_process diff --git a/docs/reference/04-process_executions_and_logs.md b/docs/reference/04-process_executions_and_logs.md index 6ab0621..25712d7 100644 --- a/docs/reference/04-process_executions_and_logs.md +++ b/docs/reference/04-process_executions_and_logs.md @@ -174,7 +174,19 @@ When `store_in_database` is `true` (default), log records are also stored in the | `context` | Log record context. | | `createdAt` | Date of the log record. | -Records are buffered and inserted every 500 records, and at the end (or failure) of the process. +The lengths are counted in characters (Unicode code points, as MySQL and PostgreSQL do): an emoji or a letter with +combining marks may count several characters. The invalid UTF-8 sequences of the message and the channel are replaced +by `?` and their NUL characters removed; a context which cannot be encoded in JSON is stored with its invalid UTF-8 sequences replaced by `U+FFFD` (`�`) +and its values which cannot be encoded (e.g. a resource) replaced by `null`. + +Records are buffered and inserted every 500 records, and at the end (or failure) of the process. When the insertion of +the log records fails (e.g. a database error), they are dropped and the failure is logged as an error on the +`cleverage_process` channel (in the [log file](#log-file), not in database): the process goes on, and the status of its +execution is saved. The entity manager is shared with the process tasks: when changes of their entities are pending +(e.g. persisted by a task, not flushed yet), they are written with the log records, and a failure is not caught, as any +error of the tasks. To know it, when entities of the tasks are managed by the entity manager, their changes are computed +before each insertion of the log records (and again by the flush): a cost proportional to the number of managed +entities, every 500 log records. On processes logging a lot, storing logs in database may be slow and memory consuming: raise `database_level`, or disable `store_in_database` and rely on the log file (see [troubleshooting](../troubleshooting.md)). diff --git a/src/Entity/LogRecord.php b/src/Entity/LogRecord.php index 64c3d78..e3f9db6 100644 --- a/src/Entity/LogRecord.php +++ b/src/Entity/LogRecord.php @@ -15,7 +15,6 @@ use Doctrine\DBAL\Types\Types; use Doctrine\ORM\Mapping as ORM; -use Symfony\Component\String\UnicodeString; #[ORM\Entity] #[ORM\Table(name: 'log_record')] @@ -55,13 +54,43 @@ public function __construct( #[ORM\JoinColumn(name: 'process_execution_id', referencedColumnName: 'id', nullable: false, onDelete: 'CASCADE')] private readonly ProcessExecution $processExecution, ) { - $this->channel = (string) (new UnicodeString($record->channel))->truncate(64); + $this->channel = $this->truncate($record->channel, 64); $this->level = $record->level->value; - $this->message = (string) (new UnicodeString($record->message))->truncate(512); - $this->context = $record->context; + $this->message = $this->truncate($record->message, 512); + $this->context = $this->encodableContext($record->context); $this->createdAt = $record->datetime; } + /** + * Invalid UTF-8 sequences replaced (by "?"), NUL characters removed (rejected by PostgreSQL, or the value truncated + * there), truncated to the length of the column: a number of characters (code points) in the database, not of + * graphemes (an emoji or a letter with combining marks is a grapheme of several code points). + */ + private function truncate(string $value, int $length): string + { + return mb_substr(str_replace("\0", '', mb_scrub($value, 'UTF-8')), 0, $length, 'UTF-8'); + } + + /** + * The context, stored as JSON: unchanged when it can be encoded, otherwise its JSON representation where the + * invalid UTF-8 sequences are replaced (by U+FFFD) and the values which cannot be encoded (e.g. a resource) are + * replaced by null: the insertion of the log record, and of the other ones of the batch, would fail. + * + * @param array $context + * + * @return array + */ + private function encodableContext(array $context): array + { + if (false !== json_encode($context, \JSON_PRESERVE_ZERO_FRACTION)) { + return $context; + } + $json = json_encode($context, \JSON_PRESERVE_ZERO_FRACTION | \JSON_INVALID_UTF8_SUBSTITUTE | \JSON_PARTIAL_OUTPUT_ON_ERROR); + $encodable = false === $json ? null : json_decode($json, true); + + return \is_array($encodable) ? $encodable : []; + } + /** * Not named hasContext(): the PropertyAccessor would use it to read the "context" property (e.g. in EasyAdmin). */ diff --git a/src/Monolog/Handler/DoctrineProcessHandler.php b/src/Monolog/Handler/DoctrineProcessHandler.php index 2a14f40..1b1eb7a 100644 --- a/src/Monolog/Handler/DoctrineProcessHandler.php +++ b/src/Monolog/Handler/DoctrineProcessHandler.php @@ -20,6 +20,7 @@ use Monolog\Handler\AbstractProcessingHandler; use Monolog\Level; use Monolog\LogRecord; +use Psr\Log\LoggerInterface; /** * @internal @@ -31,6 +32,8 @@ class DoctrineProcessHandler extends AbstractProcessingHandler private ?EntityManagerInterface $em = null; private ?ProcessExecutionManager $processExecutionManager = null; private bool $enabled = true; + private ?LoggerInterface $logger = null; + private bool $reportingFailure = false; public function __construct(int|string|Level $level = Level::Debug, bool $bubble = true) { @@ -48,6 +51,14 @@ public function setProcessExecutionManager(ProcessExecutionManager $processExecu $this->processExecutionManager = $processExecutionManager; } + /** + * Logger reporting the failures to store the logs in database (the log records are dropped, the process goes on). + */ + public function setLogger(?LoggerInterface $logger): void + { + $this->logger = $logger; + } + public function disable(): void { $this->enabled = false; @@ -70,27 +81,54 @@ public function flush(): void // or saving the process execution, see ProcessExecutionRepository::getManaged()) return; } + if ($this->records->isEmpty()) { + // Writes the changes pending in the entity manager, shared with the process tasks: their errors are not + // caught + $this->em?->flush(); + + return; + } + // Dropped even if their writing fails: they would be written again, and fail again, with the next ones + $records = $this->records; + $this->records = new ArrayCollection(); $entities = []; - $currentProcessExecution = $this->records->isEmpty() ? null : $this->processExecutionManager?->getManagedProcessExecution(); - foreach ($this->records as $record) { - if ($currentProcessExecution instanceof ProcessExecution) { - $entity = new \CleverAge\UiProcessBundle\Entity\LogRecord($record, $currentProcessExecution); - $this->em?->persist($entity); - $entities[] = $entity; + try { + $currentProcessExecution = $this->processExecutionManager?->getManagedProcessExecution(); + foreach ($records as $record) { + if ($currentProcessExecution instanceof ProcessExecution) { + $entity = new \CleverAge\UiProcessBundle\Entity\LogRecord($record, $currentProcessExecution); + $this->em?->persist($entity); + $entities[] = $entity; + } } + } catch (\Throwable $exception) { + $this->onWriteFailure($exception, $records->count(), $entities); + + return; + } + $onlyLogs = $this->hasOnlyLogsToWrite($currentProcessExecution, $entities); + try { + $this->em?->flush(); + } catch (\Throwable $exception) { + if (!$onlyLogs) { + // The entity manager is shared with the process tasks: the failure may come from their entities + throw $exception; + } + // The logs must neither make the process fail nor prevent saving the status of its execution + $this->onWriteFailure($exception, $records->count(), $entities); + + return; } - $this->em?->flush(); // Written log records are no longer needed: detached so that the identity map does not grow during long // processes (detach is not cascaded to the process execution, see LogRecord::$processExecution) foreach ($entities as $entity) { $this->em?->detach($entity); } - $this->records = new ArrayCollection(); } /** - * Drop the records not written at the end of the previous process execution (failed flush), e.g. between two - * messages of a long-running worker: they would be attached to the next one. + * Drop the records not written at the end of the previous process execution (logged after its last flush), e.g. + * between two messages of a long-running worker: they would be attached to the next one. */ #[\Override] public function reset(): void @@ -104,9 +142,97 @@ protected function write(LogRecord $record): void if (!$this->enabled) { return; } + if ($this->reportingFailure) { + // The failure of the writing is not stored in database + return; + } $this->records->add($record); - if (500 === $this->records->count()) { + if ($this->records->count() >= 500) { $this->flush(); } } + + /** + * Only the log records and the current process execution are to be written by the flush: no change of the entities + * of the process tasks, sharing the entity manager (an error of the computation of the changes, e.g. a new entity + * not persisted, is not caught). + * + * @param list<\CleverAge\UiProcessBundle\Entity\LogRecord> $entities + */ + private function hasOnlyLogsToWrite(?ProcessExecution $currentProcessExecution, array $entities): bool + { + if (!$this->em instanceof EntityManagerInterface) { + return true; + } + $ownEntities = []; + foreach ([...$entities, $currentProcessExecution] as $entity) { + if (null !== $entity) { + $ownEntities[spl_object_id($entity)] = true; + } + } + $isOwnEntity = static fn (object $entity): bool => isset($ownEntities[spl_object_id($entity)]); + $unitOfWork = $this->em->getUnitOfWork(); + // Known without computing the changes + foreach ($unitOfWork->getScheduledEntityInsertions() as $entity) { + if (!$isOwnEntity($entity)) { + return false; + } + } + if ([] !== $unitOfWork->getScheduledEntityDeletions() || [] !== $unitOfWork->getScheduledCollectionDeletions()) { + return false; + } + $onlyOwnEntitiesManaged = true; + foreach ($unitOfWork->getIdentityMap() as $managedEntities) { + foreach ($managedEntities as $entity) { + if (!$isOwnEntity($entity)) { + $onlyOwnEntitiesManaged = false; + break 2; + } + } + } + if ($onlyOwnEntitiesManaged) { + // No entity of the tasks to update + return true; + } + // The updates of the managed entities are known once the changes computed (computed again by the flush) + $unitOfWork->computeChangeSets(); + foreach ($unitOfWork->getScheduledEntityUpdates() as $entity) { + if (!$isOwnEntity($entity)) { + return false; + } + } + + return [] === $unitOfWork->getScheduledCollectionUpdates() && [] === $unitOfWork->getScheduledCollectionDeletions(); + } + + /** + * @param list<\CleverAge\UiProcessBundle\Entity\LogRecord> $entities + */ + private function onWriteFailure(\Throwable $exception, int $count, array $entities): void + { + $this->reportingFailure = true; + try { + $this->logger?->error( + \sprintf('%d log record(s) could not be stored in database: %s', $count, $exception->getMessage()), + ['exception' => $exception] + ); + } finally { + $this->reportingFailure = false; + } + if (true === $this->em?->isOpen()) { + // Not inserted by the next flush, e.g. when saving the process execution + foreach ($entities as $entity) { + $this->em->detach($entity); + } + + return; + } + try { + // Closed by Doctrine after the failure of the flush: reset right away for the process tasks (see + // ProcessExecutionRepository::getManaged()) + $this->processExecutionManager?->getManagedProcessExecution(); + } catch (\Throwable) { + // E.g. the database is still unavailable: reset again before the next writing + } + } } diff --git a/tests/DependencyInjection/CleverAgeUiProcessExtensionTest.php b/tests/DependencyInjection/CleverAgeUiProcessExtensionTest.php index ec9ff03..5d1159a 100644 --- a/tests/DependencyInjection/CleverAgeUiProcessExtensionTest.php +++ b/tests/DependencyInjection/CleverAgeUiProcessExtensionTest.php @@ -145,6 +145,9 @@ public function testLoadWithDefaultConfiguration(): void $databaseHandler = $container->getDefinition('cleverage_ui_process.monolog_handler.doctrine_process'); self::assertSame('Info', $databaseHandler->getArgument('$level')); self::assertFalse($databaseHandler->hasMethodCall('disable')); + // Failures to store the logs reported on the channel of the process logs (logger set by the MonologBundle) + self::assertTrue($databaseHandler->hasMethodCall('setLogger')); + self::assertSame([['channel' => 'cleverage_process']], $databaseHandler->getTag('monolog.logger')); $purgeLogsCommand = $container->getDefinition('cleverage_ui_process.command.purge_logs'); self::assertNull($purgeLogsCommand->getArgument('$databaseMaxDays')); diff --git a/tests/Entity/LogRecordTest.php b/tests/Entity/LogRecordTest.php index c60f76d..2ce6465 100644 --- a/tests/Entity/LogRecordTest.php +++ b/tests/Entity/LogRecordTest.php @@ -17,6 +17,7 @@ use CleverAge\UiProcessBundle\Entity\ProcessExecution; use Monolog\Level; use PHPUnit\Framework\Attributes\CoversClass; +use PHPUnit\Framework\Attributes\DataProvider; use PHPUnit\Framework\Attributes\UsesClass; use PHPUnit\Framework\TestCase; use Symfony\Component\PropertyAccess\PropertyAccess; @@ -72,6 +73,95 @@ public function testAccessors(): void self::assertSame('2026-01-01 10:00:00', $record->createdAt->format('Y-m-d H:i:s')); } + public function testInvalidUtf8MessageAndChannelAreScrubbed(): void + { + $record = new LogRecord( + new \Monolog\LogRecord(new \DateTimeImmutable(), "chan\xE9l", Level::Info, "caf\xE9 cr\xE8me"), + new ProcessExecution('demo.process', 'demo.process.log') + ); + + self::assertSame('chan?l', $record->channel); + self::assertSame('caf? cr?me', $record->message); + } + + public function testNulCharactersAreRemovedFromMessageAndChannel(): void + { + $record = new LogRecord( + new \Monolog\LogRecord(new \DateTimeImmutable(), "chan\0nel", Level::Info, "before\0after"), + new ProcessExecution('demo.process', 'demo.process.log') + ); + + self::assertSame('channel', $record->channel); + self::assertSame('beforeafter', $record->message); + } + + public function testInvalidUtf8ContextIsEncodable(): void + { + $record = $this->createLogRecord(['input' => ['name' => "caf\xE9", "k\xE9y" => 1.0], 'valid' => 'été']); + + // The invalid sequences are replaced, the rest of the context is kept + self::assertSame(['input' => ['name' => "caf\u{FFFD}", "k\u{FFFD}y" => 1.0], 'valid' => 'été'], $record->context); + self::assertNotFalse(json_encode($record->context)); + } + + public function testContextWithValuesWhichCannotBeEncoded(): void + { + $resource = fopen('php://memory', 'r'); + self::assertIsResource($resource); + try { + $record = $this->createLogRecord(['resource' => $resource, 'name' => 'value']); + } finally { + fclose($resource); + } + + self::assertSame(['resource' => null, 'name' => 'value'], $record->context); + } + + public function testEncodableContextIsUnchanged(): void + { + $object = new \stdClass(); + $object->name = 'value'; + $context = ['object' => $object, 'float' => 1.0, 'list' => [1, 2], 'emoji' => '👨‍👩‍👧‍👦']; + + self::assertSame($context, $this->createLogRecord($context)->context); + } + + /** + * @return iterable + */ + public static function provideGraphemes(): iterable + { + // 7 code points (4 emojis joined by 3 zero width joiners) for a single grapheme + yield 'family emoji' => ['👨‍👩‍👧‍👦']; + // 2 code points for a single grapheme + yield 'combining mark' => ["e\u{301}"]; + yield 'multibyte character' => ['é']; + } + + #[DataProvider('provideGraphemes')] + public function testMessageIsTruncatedToTheColumnLengthInCodePoints(string $grapheme): void + { + $message = str_repeat($grapheme, 600); + $record = new LogRecord( + new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Info, $message), + new ProcessExecution('demo.process', 'demo.process.log') + ); + + // The length of the column counts characters (code points), not graphemes nor bytes + self::assertSame(512, mb_strlen($record->message)); + self::assertSame(mb_substr($message, 0, 512), $record->message); + } + + public function testChannelIsTruncatedToTheColumnLengthInCodePoints(): void + { + $record = new LogRecord( + new \Monolog\LogRecord(new \DateTimeImmutable(), str_repeat("e\u{301}", 40), Level::Info, 'message'), + new ProcessExecution('demo.process', 'demo.process.log') + ); + + self::assertSame(64, mb_strlen($record->channel)); + } + /** * @param array $context */ diff --git a/tests/EventSubscriber/ProcessEventSubscriberTest.php b/tests/EventSubscriber/ProcessEventSubscriberTest.php index 3d4c329..10b4130 100644 --- a/tests/EventSubscriber/ProcessEventSubscriberTest.php +++ b/tests/EventSubscriber/ProcessEventSubscriberTest.php @@ -26,6 +26,7 @@ use CleverAge\UiProcessBundle\Monolog\Handler\ProcessHandler; use CleverAge\UiProcessBundle\Repository\ProcessExecutionRepository; use Doctrine\ORM\EntityManagerInterface; +use Doctrine\ORM\UnitOfWork; use Monolog\Level; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\DataProvider; @@ -279,7 +280,14 @@ public function testFlushDoctrineLogs(): void $processExecutionManager = new ProcessExecutionManager($this->createRepositoryStub()); $processExecutionManager->setCurrentProcessExecution(new ProcessExecution('test.process', 'test.log')); + // doctrine/orm 2: no native return types, a mock would return null + $unitOfWork = $this->createStub(UnitOfWork::class); + $unitOfWork->method('getScheduledEntityInsertions')->willReturn([]); + $unitOfWork->method('getScheduledEntityDeletions')->willReturn([]); + $unitOfWork->method('getScheduledCollectionDeletions')->willReturn([]); + $unitOfWork->method('getIdentityMap')->willReturn([]); $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager->method('getUnitOfWork')->willReturn($unitOfWork); $entityManager->expects(self::once())->method('persist')->with(self::isInstanceOf(LogRecord::class)); $entityManager->expects(self::atLeastOnce())->method('flush'); @@ -296,6 +304,7 @@ public function testFlushDoctrineLogs(): void $processExecutionManager ); $subscriber->flushDoctrineLogs(new ProcessEvent('test.process')); + $doctrineProcessHandler->disable(); // no flush on destruction, during another test } private function createSubscriber( diff --git a/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php b/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php index 167d5a8..69359fb 100644 --- a/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php +++ b/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php @@ -13,6 +13,7 @@ namespace CleverAge\UiProcessBundle\Tests\Monolog\Handler; +use CleverAge\ProcessBundle\Event\ProcessEvent; use CleverAge\UiProcessBundle\CleverAgeUiProcessBundle; use CleverAge\UiProcessBundle\DependencyInjection\CleverAgeUiProcessExtension; use CleverAge\UiProcessBundle\DependencyInjection\Compiler\CheckDoctrineLazyGhostObjectsPass; @@ -22,15 +23,23 @@ use CleverAge\UiProcessBundle\Entity\Enum\ProcessExecutionStatus; use CleverAge\UiProcessBundle\Entity\LogRecord; use CleverAge\UiProcessBundle\Entity\ProcessExecution; +use CleverAge\UiProcessBundle\Entity\User; use CleverAge\UiProcessBundle\EventSubscriber\ProcessEventSubscriber; use CleverAge\UiProcessBundle\Manager\ProcessExecutionManager; use CleverAge\UiProcessBundle\Monolog\Handler\DoctrineProcessHandler; +use CleverAge\UiProcessBundle\Monolog\Handler\ProcessHandler; use CleverAge\UiProcessBundle\Repository\ProcessExecutionRepository; use CleverAge\UiProcessBundle\Routing\DeprecatedEasyAdminRouteAliasLoader; use CleverAge\UiProcessBundle\Tests\App\TestKernel; +use Doctrine\DBAL\Exception\UniqueConstraintViolationException; use Doctrine\ORM\EntityManagerInterface; +use Doctrine\ORM\Event\OnFlushEventArgs; +use Doctrine\ORM\Events; use Doctrine\ORM\Tools\SchemaTool; +use Doctrine\Persistence\ManagerRegistry; +use Monolog\Handler\TestHandler; use Monolog\Level; +use Monolog\Logger; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; use Symfony\Bundle\FrameworkBundle\Test\KernelTestCase; @@ -51,6 +60,8 @@ #[UsesClass(ProcessExecution::class)] #[UsesClass(ProcessExecutionManager::class)] #[UsesClass(ProcessExecutionRepository::class)] +#[UsesClass(ProcessHandler::class)] +#[UsesClass(User::class)] class DoctrineProcessHandlerEntityManagerTest extends KernelTestCase { private EntityManagerInterface $entityManager; @@ -109,4 +120,216 @@ public function testWrittenLogRecordsAreDetached(): void $connection->fetchAllAssociative('SELECT process_execution_id, COUNT(*) AS count FROM log_record GROUP BY process_execution_id') ); } + + public function testInvalidUtf8AndLongMessagesAreStored(): void + { + $processExecutionManager = new ProcessExecutionManager(new ProcessExecutionRepository($this->entityManager)); + $processExecutionManager->setCurrentProcessExecution(new ProcessExecution('test.process', 'test.log'))->save(); + $handler = new DoctrineProcessHandler(); + $handler->setEntityManager($this->entityManager); + $handler->setProcessExecutionManager($processExecutionManager); + + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, "caf\xE9", ['input' => "cr\xE8me"])); + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, str_repeat('👨‍👩‍👧‍👦', 100))); + $handler->flush(); + $handler->disable(); + + // SQLite does not check the length of the columns (MySQL and PostgreSQL count code points) + /** @var list $logRecords */ + $logRecords = $this->entityManager->getConnection()->fetchAllAssociative('SELECT message, context FROM log_record ORDER BY id'); + self::assertCount(2, $logRecords); + self::assertSame('caf?', $logRecords[0]['message']); + self::assertSame(['input' => "cr\u{FFFD}me"], json_decode($logRecords[0]['context'], true)); + self::assertSame(512, mb_strlen($logRecords[1]['message'])); + } + + /** + * The failure to store the logs does not prevent saving the status of the process execution. + */ + public function testFlushFailureAtTheEndOfTheProcess(): void + { + /** @var ManagerRegistry $registry */ + $registry = static::getContainer()->get('doctrine'); + $manager = new ProcessExecutionManager(new ProcessExecutionRepository($this->entityManager, $registry)); + $handler = new DoctrineProcessHandler(); + $handler->setEntityManager($this->entityManager); + $handler->setProcessExecutionManager($manager); + $logger = new TestHandler(); + $handler->setLogger(new Logger('cleverage_process', [$logger])); + $processHandler = new ProcessHandler(sys_get_temp_dir(), $manager); + $processHandler->setFilename('test.process/test.log'); + $subscriber = new ProcessEventSubscriber($processHandler, $handler, $manager); + $connection = $this->entityManager->getConnection(); + + $event = new ProcessEvent('test.process'); + $subscriber->onProcessStart($event); + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'written')); + $handler->flush(); + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'lost')); + + // The insertion of the log records fails (Doctrine closes the entity manager) + $connection->executeStatement('ALTER TABLE log_record RENAME TO log_record_renamed'); + try { + // ProcessEvent::EVENT_PROCESS_ENDED listeners + $subscriber->flushDoctrineLogs($event); + // Reset right away for the process tasks + self::assertTrue($this->entityManager->isOpen()); + $subscriber->success($event); + } finally { + $connection->executeStatement('ALTER TABLE log_record_renamed RENAME TO log_record'); + } + + self::assertSame( + [['code' => 'test.process', 'status' => 'finish']], + $connection->fetchAllAssociative('SELECT code, status FROM process_execution') + ); + self::assertSame(['written'], $connection->fetchFirstColumn('SELECT message FROM log_record ORDER BY id')); + self::assertTrue($logger->hasErrorThatContains('1 log record(s) could not be stored in database')); + self::assertTrue($this->entityManager->isOpen()); + + // The failed records are not written again + $handler->flush(); + self::assertSame(['written'], $connection->fetchFirstColumn('SELECT message FROM log_record ORDER BY id')); + $handler->disable(); + } + + /** + * The entity manager is shared with the process tasks: the errors of their pending changes are not caught, as + * before. + */ + public function testErrorOfAPendingTaskEntityIsNotCaught(): void + { + $handler = $this->createHandlerWithLogger($logger = new TestHandler()); + $this->entityManager->persist((new User())->setEmail('user@example.com')); + $this->entityManager->flush(); + // Persisted by a task, not flushed: violates the unique constraint + $this->entityManager->persist((new User())->setEmail('user@example.com')); + + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'message')); + try { + $handler->flush(); + self::fail('The error of the task entity is not caught'); + } catch (UniqueConstraintViolationException) { + } + self::assertSame([], $logger->getRecords()); + $handler->setLogger(null); + $handler->disable(); + } + + public function testErrorOfAPendingTaskEntityWithoutLogRecordsIsNotCaught(): void + { + $handler = $this->createHandlerWithLogger(new TestHandler()); + $this->entityManager->persist((new User())->setEmail('user@example.com')); + $this->entityManager->flush(); + $this->entityManager->persist((new User())->setEmail('user@example.com')); + + $this->expectException(UniqueConstraintViolationException::class); + try { + $handler->flush(); + } finally { + $handler->setLogger(null); + $handler->disable(); + } + } + + /** + * A failure before the transaction (the entity manager stays open), e.g. an application listener rejecting an + * entity of a task. + */ + public function testFailureOfAnOnFlushListenerOnATaskEntityIsNotCaught(): void + { + $handler = $this->createHandlerWithLogger($logger = new TestHandler()); + $this->entityManager->getEventManager()->addEventListener([Events::onFlush], $listener = new class { + public function onFlush(OnFlushEventArgs $args): void + { + foreach ($args->getObjectManager()->getUnitOfWork()->getScheduledEntityInsertions() as $entity) { + if ($entity instanceof User) { + throw new \DomainException('Invalid user'); + } + } + } + }); + $this->entityManager->persist((new User())->setEmail('user@example.com')); + + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'message')); + try { + $handler->flush(); + self::fail('The error of the task entity is not caught'); + } catch (\DomainException $exception) { + self::assertSame('Invalid user', $exception->getMessage()); + } finally { + $this->entityManager->getEventManager()->removeEventListener([Events::onFlush], $listener); + } + self::assertSame([], $logger->getRecords()); + $handler->setLogger(null); + $handler->disable(); + } + + public function testErrorOfAnotherProcessExecutionChangedByATaskIsNotCaught(): void + { + $other = new ProcessExecution('other.process', 'other.log'); + $this->entityManager->persist($other); + $this->entityManager->flush(); + $handler = $this->createHandlerWithLogger($logger = new TestHandler()); + $this->entityManager->getEventManager()->addEventListener([Events::onFlush], $listener = new class { + public function onFlush(OnFlushEventArgs $args): void + { + foreach ($args->getObjectManager()->getUnitOfWork()->getScheduledEntityUpdates() as $entity) { + if ($entity instanceof ProcessExecution && 'other.process' === $entity->getCode()) { + throw new \DomainException('Invalid process execution'); + } + } + } + }); + $other->setStatus(ProcessExecutionStatus::Failed); // by a task + + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'message')); + try { + $handler->flush(); + self::fail('The error of the task entity is not caught'); + } catch (\DomainException $exception) { + self::assertSame('Invalid process execution', $exception->getMessage()); + } finally { + $this->entityManager->getEventManager()->removeEventListener([Events::onFlush], $listener); + } + self::assertSame([], $logger->getRecords()); + $handler->setLogger(null); + $handler->disable(); + } + + /** + * The failure is reported even when the entity manager cannot be reset (the database is still unavailable). + */ + public function testFailureIsReportedWhenTheDatabaseIsUnavailable(): void + { + $handler = $this->createHandlerWithLogger($logger = new TestHandler()); + $connection = $this->entityManager->getConnection(); + $handler->handle(new \Monolog\LogRecord(new \DateTimeImmutable(), 'cleverage_process', Level::Warning, 'message')); + $connection->executeStatement('ALTER TABLE log_record RENAME TO log_record_renamed'); + $connection->executeStatement('ALTER TABLE process_execution RENAME TO process_execution_renamed'); + try { + // The flush fails and closes the entity manager, which is reset: the process execution cannot be read again + $handler->flush(); + } finally { + $connection->executeStatement('ALTER TABLE log_record_renamed RENAME TO log_record'); + $connection->executeStatement('ALTER TABLE process_execution_renamed RENAME TO process_execution'); + } + self::assertTrue($logger->hasErrorThatContains('1 log record(s) could not be stored in database')); + $handler->setLogger(null); + $handler->disable(); + } + + private function createHandlerWithLogger(TestHandler $logger): DoctrineProcessHandler + { + /** @var ManagerRegistry $registry */ + $registry = static::getContainer()->get('doctrine'); + $manager = new ProcessExecutionManager(new ProcessExecutionRepository($this->entityManager, $registry)); + $manager->setCurrentProcessExecution(new ProcessExecution('test.process', 'test.log'))->save(); + $handler = new DoctrineProcessHandler(); + $handler->setEntityManager($this->entityManager); + $handler->setProcessExecutionManager($manager); + $handler->setLogger(new Logger('cleverage_process', [$logger])); + + return $handler; + } } diff --git a/tests/Monolog/Handler/DoctrineProcessHandlerTest.php b/tests/Monolog/Handler/DoctrineProcessHandlerTest.php index b6e9f80..a6ed31f 100644 --- a/tests/Monolog/Handler/DoctrineProcessHandlerTest.php +++ b/tests/Monolog/Handler/DoctrineProcessHandlerTest.php @@ -19,10 +19,16 @@ use CleverAge\UiProcessBundle\Monolog\Handler\DoctrineProcessHandler; use CleverAge\UiProcessBundle\Repository\ProcessExecutionRepository; use Doctrine\ORM\EntityManagerInterface; +use Doctrine\ORM\UnitOfWork; +use Monolog\Handler\TestHandler; use Monolog\Level; +use Monolog\Logger; use PHPUnit\Framework\Attributes\CoversClass; +use PHPUnit\Framework\Attributes\DataProvider; use PHPUnit\Framework\Attributes\UsesClass; +use PHPUnit\Framework\MockObject\MockObject; use PHPUnit\Framework\TestCase; +use Psr\Log\LoggerInterface; #[CoversClass(DoctrineProcessHandler::class)] #[UsesClass(LogRecord::class)] @@ -35,7 +41,7 @@ public function testRecordsArePersistedOnFlush(): void $processExecution = new ProcessExecution('test.process', 'test.log'); /** @var \ArrayObject $persisted */ $persisted = new \ArrayObject(); - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->method('isOpen')->willReturn(true); $entityManager->expects(self::exactly(2)) ->method('persist') @@ -76,7 +82,7 @@ public function testRecordsArePersistedOnFlush(): void public function testRecordsAreFlushedEvery500Records(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->expects(self::exactly(500))->method('persist'); $entityManager->expects(self::once())->method('flush'); @@ -89,7 +95,7 @@ public function testRecordsAreFlushedEvery500Records(): void public function testRecordsAreFlushedOnDestruction(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->expects(self::once())->method('persist')->with(self::isInstanceOf(LogRecord::class)); $entityManager->expects(self::once())->method('flush'); @@ -100,7 +106,7 @@ public function testRecordsAreFlushedOnDestruction(): void public function testRecordsAreDroppedWithoutProcessExecution(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->expects(self::never())->method('persist'); $entityManager->expects(self::once())->method('flush'); $entityManager->expects(self::never())->method('detach'); @@ -113,7 +119,7 @@ public function testRecordsAreDroppedWithoutProcessExecution(): void public function testClosedEntityManagerWithoutRecords(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->method('isOpen')->willReturn(false); $entityManager->expects(self::never())->method('flush'); @@ -123,7 +129,7 @@ public function testClosedEntityManagerWithoutRecords(): void public function testOpenEntityManagerWithoutRecords(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->method('isOpen')->willReturn(true); $entityManager->expects(self::once())->method('flush'); @@ -134,7 +140,7 @@ public function testOpenEntityManagerWithoutRecords(): void public function testDisabledHandler(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->expects(self::never())->method('persist'); $entityManager->expects(self::never())->method('flush'); @@ -156,7 +162,7 @@ public function testWithoutEntityManagerNorProcessExecutionManager(): void public function testResetDropsTheRecordsNotWritten(): void { - $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager = $this->createEntityManagerMock(); $entityManager->method('isOpen')->willReturn(true); $entityManager->expects(self::never())->method('persist'); @@ -167,6 +173,231 @@ public function testResetDropsTheRecordsNotWritten(): void $handler->disable(); // no flush on destruction } + public function testFlushFailureDropsTheRecordsAndIsReported(): void + { + /** @var \ArrayObject $persisted */ + $persisted = new \ArrayObject(); + /** @var \ArrayObject $detached */ + $detached = new \ArrayObject(); + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->method('persist')->willReturnCallback(static function (object $entity) use ($persisted): void { + $persisted[] = $entity; + }); + $entityManager->method('detach')->willReturnCallback(static function (object $entity) use ($detached): void { + $detached[] = $entity; + }); + $failure = new \RuntimeException('Data too long'); + $entityManager->expects(self::exactly(2)) + ->method('flush') + ->willReturnOnConsecutiveCalls(self::throwException($failure), null); + $logger = $this->createMock(LoggerInterface::class); + $logger->expects(self::once()) + ->method('error') + ->with('2 log record(s) could not be stored in database: Data too long', ['exception' => $failure]); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $handler->setLogger($logger); + $handler->handle($this->createRecord(Level::Info, 'first')); + $handler->handle($this->createRecord(Level::Info, 'second')); + $handler->flush(); // does not throw + + // Not inserted by the next flush (e.g. saving the process execution) when the entity manager is still open + self::assertCount(2, $persisted); + self::assertSame($persisted->getArrayCopy(), $detached->getArrayCopy()); + + // The failed records are dropped: only the next ones are written + $handler->handle($this->createRecord(Level::Info, 'third')); + $handler->flush(); + self::assertCount(3, $persisted); + self::assertInstanceOf(LogRecord::class, $persisted[2]); + self::assertSame('third', $persisted[2]->message); + $handler->disable(); + } + + /** + * @return iterable>}> + */ + public static function provideTaskChanges(): iterable + { + $taskEntity = new \stdClass(); + $managed = ['getIdentityMap' => [\stdClass::class => [1 => $taskEntity]]]; + yield 'insertion' => [['getScheduledEntityInsertions' => [$taskEntity]]]; + yield 'update' => [$managed + ['getScheduledEntityUpdates' => [$taskEntity]]]; + yield 'deletion' => [['getScheduledEntityDeletions' => [$taskEntity]]]; + yield 'collection update' => [$managed + ['getScheduledCollectionUpdates' => [$taskEntity]]]; + yield 'collection deletion' => [['getScheduledCollectionDeletions' => [$taskEntity]]]; + $otherProcessExecution = new ProcessExecution('other.process', 'other.log'); + yield 'other process execution' => [['getIdentityMap' => [ProcessExecution::class => [1 => $otherProcessExecution]], 'getScheduledEntityUpdates' => [$otherProcessExecution]]]; + } + + /** + * The entity manager is shared with the process tasks: the failure may come from their pending changes. + * + * @param array> $unitOfWorkResults + */ + #[DataProvider('provideTaskChanges')] + public function testFlushFailureWithChangesOfTheTasksIsNotCaught(array $unitOfWorkResults): void + { + $entityManager = $this->createEntityManagerMock($unitOfWorkResults); + $entityManager->method('isOpen')->willReturn(true); + $failure = new \RuntimeException('Failure of a task entity'); + $entityManager->expects(self::once())->method('flush')->willThrowException($failure); + $logger = $this->createMock(LoggerInterface::class); + $logger->expects(self::never())->method('error'); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $handler->setLogger($logger); + $handler->handle($this->createRecord(Level::Info, 'message')); + try { + $handler->flush(); + self::fail('The failure is not caught'); + } catch (\RuntimeException $exception) { + self::assertSame($failure, $exception); + } + $handler->disable(); + } + + /** + * The current process execution updated (report), entities of the tasks managed without changes. + */ + public function testFlushFailureWithoutChangesOfTheTasksIsCaught(): void + { + $processExecution = new ProcessExecution('test.process', 'test.log'); + $entityManager = $this->createEntityManagerMock([ + 'getIdentityMap' => [ProcessExecution::class => [1 => $processExecution], \stdClass::class => [1 => new \stdClass()]], + 'getScheduledEntityUpdates' => [$processExecution], + ]); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->expects(self::once())->method('flush')->willThrowException(new \RuntimeException('Failure')); + $logger = $this->createMock(LoggerInterface::class); + $logger->expects(self::once())->method('error'); + + $handler = $this->createHandler($entityManager, $processExecution); + $handler->setLogger($logger); + $handler->handle($this->createRecord(Level::Info, 'message')); + $handler->flush(); + $handler->disable(); + } + + public function testPersistFailureIsCaught(): void + { + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->method('persist')->willThrowException(new \RuntimeException('Failure')); + $entityManager->expects(self::never())->method('flush'); + $logger = $this->createMock(LoggerInterface::class); + $logger->expects(self::once())->method('error')->with('1 log record(s) could not be stored in database: Failure'); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $handler->setLogger($logger); + $handler->handle($this->createRecord(Level::Info, 'message')); + $handler->flush(); + $handler->disable(); + } + + public function testFlushFailureWithoutRecordsIsNotCaught(): void + { + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->expects(self::once())->method('flush')->willThrowException(new \RuntimeException('Failure')); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $this->expectExceptionObject(new \RuntimeException('Failure')); + try { + $handler->flush(); + } finally { + $handler->disable(); + } + } + + public function testFlushFailureWithAClosedEntityManager(): void + { + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(false); // closed by Doctrine after the failure of the flush + $entityManager->expects(self::once())->method('persist'); + $entityManager->expects(self::once())->method('flush')->willThrowException(new \RuntimeException('Failure')); + $entityManager->expects(self::never())->method('detach'); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $handler->handle($this->createRecord(Level::Info, 'message')); + $handler->flush(); // does not throw, without logger + $handler->flush(); // nothing to write anymore + $handler->disable(); + } + + public function testFlushFailureOfThe500thRecordDoesNotFail(): void + { + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->expects(self::exactly(1000))->method('persist'); + // Every 500 records again after a failure: the records do not accumulate + $entityManager->expects(self::exactly(2)) + ->method('flush') + ->willThrowException(new \RuntimeException('Failure')); + + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + for ($i = 0; $i < 1000; ++$i) { + $handler->handle($this->createRecord(Level::Debug, 'message '.$i)); + } + $handler->disable(); + } + + public function testReportedFailureIsNotStoredInDatabase(): void + { + /** @var \ArrayObject $persisted */ + $persisted = new \ArrayObject(); + $entityManager = $this->createEntityManagerMock(); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->method('persist')->willReturnCallback(static function (object $entity) use ($persisted): void { + self::assertInstanceOf(LogRecord::class, $entity); + $persisted[] = $entity; + }); + $entityManager->expects(self::exactly(2)) + ->method('flush') + ->willReturnOnConsecutiveCalls(self::throwException(new \RuntimeException('Failure')), null); + + // The failure is logged on the channel of the handler (cleverage_process): handled by the handler itself + $handler = $this->createHandler($entityManager, new ProcessExecution('test.process', 'test.log')); + $otherHandler = new TestHandler(); + $handler->setLogger(new Logger('cleverage_process', [$handler, $otherHandler])); + $handler->handle($this->createRecord(Level::Info, 'message')); + $handler->flush(); + $handler->flush(); + + // Reported to the other handlers only + self::assertCount(1, $persisted); + self::assertTrue($otherHandler->hasErrorThatContains('1 log record(s) could not be stored in database: Failure')); + $handler->disable(); + $handler->setLogger(null); // circular reference: the handler would be destructed during another test + } + + /** + * Entity manager whose unit of work has nothing else to write (doctrine/orm 2: no native return types, a mock + * would return null). + * + * @param array> $unitOfWorkResults results of the methods of the unit of work + */ + private function createEntityManagerMock(array $unitOfWorkResults = []): EntityManagerInterface&MockObject + { + $unitOfWork = $this->createStub(UnitOfWork::class); + $unitOfWorkResults += [ + 'getScheduledEntityInsertions' => [], + 'getScheduledEntityUpdates' => [], + 'getScheduledEntityDeletions' => [], + 'getScheduledCollectionUpdates' => [], + 'getScheduledCollectionDeletions' => [], + 'getIdentityMap' => [], + ]; + foreach ($unitOfWorkResults as $method => $result) { + $unitOfWork->method($method)->willReturn($result); + } + $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager->method('getUnitOfWork')->willReturn($unitOfWork); + + return $entityManager; + } + private function createHandler(EntityManagerInterface $entityManager, ?ProcessExecution $processExecution): DoctrineProcessHandler { $processExecutionManager = new ProcessExecutionManager($this->createRepositoryStub());