Issue #3305167 by kunal.sachdev, phenaproxima: Warn if apply and post-apply...

Issue #3305167 by kunal.sachdev, phenaproxima: Warn if apply and post-apply are done in same request

automatic_updates.services.yml

@@ -28,6 +28,8 @@ services:
       - '@datetime.time'
       - '@PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactoryInterface'
       - '@package_manager.failure_marker'
+    calls:
+      - ['setLogger', ['@logger.channel.automatic_updates']]
   automatic_updates.cron_updater:
     class: Drupal\automatic_updates\CronUpdater
     arguments:
@@ -47,6 +49,8 @@ services:
       - '@datetime.time'
       - '@PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactoryInterface'
       - '@package_manager.failure_marker'
+    calls:
+      - ['setLogger', ['@logger.channel.automatic_updates']]
   automatic_updates.staged_projects_validator:
     class: Drupal\automatic_updates\Validator\StagedProjectsValidator
     arguments:
@@ -151,3 +155,6 @@ services:
       - '@package_manager.path_locator'
     tags:
       - { name: event_subscriber }
+  logger.channel.automatic_updates:
+    parent: logger.channel_base
+    arguments: ['automatic_updates']

package_manager/src/Stage.php

@@ -32,6 +32,9 @@ use PhpTuf\ComposerStager\Domain\Exception\PreconditionException;
 use PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory;
 use PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactoryInterface;
 use PhpTuf\ComposerStager\Infrastructure\Value\PathList\PathList;
+use Psr\Log\LoggerAwareInterface;
+use Psr\Log\LoggerAwareTrait;
+use Psr\Log\NullLogger;
 use Symfony\Contracts\EventDispatcher\EventDispatcherInterface;
 
 /**
@@ -58,8 +61,9 @@ use Symfony\Contracts\EventDispatcher\EventDispatcherInterface;
  * (e.g. `/tmp/.package_managerSITE_UUID`), which is deleted when any stage
  * created by that site is destroyed.
  */
-class Stage {
+class Stage implements LoggerAwareInterface {
 
+  use LoggerAwareTrait;
   use StringTranslationTrait;
 
   /**
@@ -227,6 +231,7 @@ class Stage {
       $failure_marker = \Drupal::service('package_manager.failure_marker');
     }
     $this->failureMarker = $failure_marker;
+    $this->setLogger(new NullLogger());
   }
 
   /**
@@ -446,6 +451,9 @@ class Stage {
   public function postApply(): void {
     $this->checkOwnership();
 
+    if ($this->tempStore->get(self::TEMPSTORE_APPLY_TIME_KEY) === $this->time->getRequestTime()) {
+      $this->logger->warning('Post-apply tasks are running in the same request during which staged changes were applied to the active code base. This can result in unpredictable behavior.');
+    }
     // Rebuild the container and clear all caches, to ensure that new services
     // are picked up.
     drupal_flush_all_caches();

package_manager/tests/src/Kernel/StageTest.php

@@ -16,6 +16,8 @@ use PhpTuf\ComposerStager\Domain\Exception\InvalidArgumentException;
 use PhpTuf\ComposerStager\Domain\Exception\PreconditionException;
 use Drupal\package_manager_bypass\Beginner;
 use PhpTuf\ComposerStager\Domain\Service\Precondition\PreconditionInterface;
+use Psr\Log\LogLevel;
+use Psr\Log\Test\TestLogger;
 
 /**
  * @coversDefaultClass \Drupal\package_manager\Stage
@@ -406,6 +408,36 @@ class StageTest extends PackageManagerKernelTestBase {
     );
   }
 
+  /**
+   * Tests running apply and post-apply in the same request.
+   */
+  public function testApplyAndPostApplyInSameRequest(): void {
+    $stage = $this->createStage();
+
+    $logger = new TestLogger();
+    $stage->setLogger($logger);
+    $warning_message = 'Post-apply tasks are running in the same request during which staged changes were applied to the active code base. This can result in unpredictable behavior.';
+
+    // Run apply and post-apply in the same request (i.e., the same request
+    // time), and ensure the warning is logged.
+    $stage->create();
+    $stage->require(['drupal/core' => '9.8.1']);
+    $stage->apply();
+    $stage->postApply();
+    $this->assertTrue($logger->hasRecord($warning_message, LogLevel::WARNING));
+    $stage->destroy();
+
+    $logger->reset();
+    $stage->create();
+    $stage->require(['drupal/core' => '9.8.2']);
+    $stage->apply();
+    // Simulate post-apply taking place in another request by simulating a
+    // request time 30 seconds after apply started.
+    TestTime::$offset = 30;
+    $stage->postApply();
+    $this->assertFalse($logger->hasRecord($warning_message, LogLevel::WARNING));
+  }
+
 }
 
 /**

tests/src/Kernel/CronUpdaterTest.php

@@ -478,4 +478,12 @@ class CronUpdaterTest extends AutomaticUpdatesKernelTestBase {
     $this->assertSame([$expected_language_code], $sent_message['line_langcodes']);
   }
 
+  /**
+   * Tests that setLogger is called on the cron updater service.
+   */
+  public function testLoggerIsSetByContainer(): void {
+    $updater_method_calls = $this->container->getDefinition('automatic_updates.cron_updater')->getMethodCalls();
+    $this->assertSame('setLogger', $updater_method_calls[0][0]);
+  }
+
 }

tests/src/Kernel/UpdaterTest.php

@@ -188,4 +188,12 @@ class UpdaterTest extends AutomaticUpdatesKernelTestBase {
     $updater->apply();
   }
 
+  /**
+   * Tests that setLogger is called on the updater service.
+   */
+  public function testLoggerIsSetByContainer(): void {
+    $updater_method_calls = $this->container->getDefinition('automatic_updates.updater')->getMethodCalls();
+    $this->assertSame('setLogger', $updater_method_calls[0][0]);
+  }
+
 }