diff --git a/CHANGELOG.md b/CHANGELOG.md index 97cff4ce..9d5175e8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,7 @@ Latest ------ ## Fixes +* [#307](https://github.com/cleverage/ui-process-bundle/issues/307) The buffered log records are written to the database at the end (or failure) of the process of the execution only, no longer at the end of each of its sub-processes (e.g. a `ProcessExecutorTask` in a loop: one transaction per iteration, 1000 iterations took 10.5 s instead of 2.9 s). Update documentation, add tests. * [#305](https://github.com/cleverage/ui-process-bundle/issues/305) Database logs: the strings of the context of a log record are limited to 65536 characters (followed by ` [...] (over 65536 characters, total, truncated)`), as its arrays (#271): a larger string (e.g. the content of a file) over the maximum packet size of the database made the insertion of the log records written with it fail, and closed the connection shared with the process tasks. Update documentation, add tests. * [#303](https://github.com/cleverage/ui-process-bundle/issues/303) Logs list: the context filter also searches the value as encoded in JSON by Doctrine (internal `LogTextFilter`): PostgreSQL, MariaDB and SQLite keep the JSON as written (`/` written `\/`, `"` written `\"`, non-ASCII characters written `\uXXXX`), a search containing such characters (e.g. a path) found nothing there. Update documentation, add tests. * [#299](https://github.com/cleverage/ui-process-bundle/issues/299) `DoctrineProcessHandler`: below the `Error` level, a log record counted in the report is inserted right away at most every `process_execution.heartbeat_interval` seconds (new `setWriteRightAwayInterval()`), otherwise with the next ones: since 3.5, each warning was inserted with the report of the execution in a transaction of its own (5000 warnings: 60 s instead of 8 s). The records from the `Error` level are still inserted right away. Update documentation, add tests. diff --git a/docs/reference/04-process_executions_and_logs.md b/docs/reference/04-process_executions_and_logs.md index 89c22174..d0f45f99 100644 --- a/docs/reference/04-process_executions_and_logs.md +++ b/docs/reference/04-process_executions_and_logs.md @@ -201,7 +201,8 @@ truncated)` (the log file has it whole); over the maximum packet size of the dat MySQL), its log record and the ones written with it were lost, and the connection, shared with the process tasks, was closed. The objects of the context are stored with their public properties, without limit. -Records are buffered and inserted every 500 records, and at the end (or failure) of the process. A record counted in +Records are buffered and inserted every 500 records, and at the end (or failure) of the process (of the process of +the execution, not of each of its sub-processes run in the same PHP process). A record counted in the report of the execution (from `report_increment_level`, warnings by default) is inserted right away with the buffered ones, unless changes of the process tasks are pending in the entity manager (they would be written with it, see below): it is then inserted with the next ones. Below the `Error` level, it is inserted right away only when the last diff --git a/src/EventSubscriber/ProcessEventSubscriber.php b/src/EventSubscriber/ProcessEventSubscriber.php index 080bfb1f..18a7b450 100644 --- a/src/EventSubscriber/ProcessEventSubscriber.php +++ b/src/EventSubscriber/ProcessEventSubscriber.php @@ -119,8 +119,16 @@ private function dispatchEnded(ProcessEvent $event): void } } - public function flushDoctrineLogs(): void + /** + * Only at the end of the process of the current execution: the end of each of its sub-processes (e.g. a + * ProcessExecutorTask in a loop) wrote the buffered log records, in a transaction of its own. + */ + public function flushDoctrineLogs(ProcessEvent $event): void { + $currentProcessExecution = $this->processExecutionManager->getCurrentProcessExecution(); + if ($currentProcessExecution instanceof ProcessExecution && $event->getProcessCode() !== $currentProcessExecution->getCode()) { + return; + } $this->doctrineProcessHandler->flush(); } } diff --git a/tests/EventSubscriber/ProcessEventSubscriberTest.php b/tests/EventSubscriber/ProcessEventSubscriberTest.php index 0f6d5ee2..78719139 100644 --- a/tests/EventSubscriber/ProcessEventSubscriberTest.php +++ b/tests/EventSubscriber/ProcessEventSubscriberTest.php @@ -277,7 +277,10 @@ public function testFlushDoctrineLogs(): void $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'); + $flushes = 0; + $entityManager->method('flush')->willReturnCallback(static function () use (&$flushes): void { + ++$flushes; + }); $doctrineProcessHandler = new DoctrineProcessHandler(); $doctrineProcessHandler->setEntityManager($entityManager); @@ -291,10 +294,35 @@ public function testFlushDoctrineLogs(): void $doctrineProcessHandler, $processExecutionManager ); - $subscriber->flushDoctrineLogs(); + // End of a sub-process (e.g. ProcessExecutorTask): written at the end of the process of the execution + $subscriber->flushDoctrineLogs(new ProcessEvent('sub.process')); + self::assertSame(0, $flushes); + + $subscriber->flushDoctrineLogs(new ProcessEvent('test.process')); + self::assertSame(1, $flushes); $doctrineProcessHandler->disable(); // no flush on destruction, during another test } + /** + * Without current process execution (none started), the pending log records and changes are still written. + */ + public function testFlushDoctrineLogsWithoutProcessExecution(): void + { + $entityManager = $this->createMock(EntityManagerInterface::class); + $entityManager->method('isOpen')->willReturn(true); + $entityManager->expects(self::once())->method('flush'); + $doctrineProcessHandler = new DoctrineProcessHandler(); + $doctrineProcessHandler->setEntityManager($entityManager); + $processExecutionManager = new ProcessExecutionManager($this->createRepositoryStub()); + + (new ProcessEventSubscriber( + new ProcessHandler('/var/log/process', $processExecutionManager), + $doctrineProcessHandler, + $processExecutionManager + ))->flushDoctrineLogs(new ProcessEvent('test.process')); + $doctrineProcessHandler->disable(); + } + private function createSubscriber( ProcessHandler $processHandler, ProcessExecutionManager $processExecutionManager, diff --git a/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php b/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php index 6335e47a..5e434635 100644 --- a/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php +++ b/tests/Monolog/Handler/DoctrineProcessHandlerEntityManagerTest.php @@ -186,7 +186,7 @@ public function testFlushFailureAtTheEndOfTheProcess(): void $connection->executeStatement('ALTER TABLE log_record RENAME TO log_record_renamed'); try { // ProcessEvent::EVENT_PROCESS_ENDED listeners - $subscriber->flushDoctrineLogs(); + $subscriber->flushDoctrineLogs($event); // Reset right away for the process tasks self::assertTrue($this->entityManager->isOpen()); $subscriber->success($event);