#307 - Write the buffered logs at the end of the process of the execution only

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, <count> 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.

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

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();
     }
 }

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,

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);