Issue #3319045 by tedbow, kunal.sachdev, Wim Leers: Assert that all expected...

Issue #3319045 by tedbow, kunal.sachdev, Wim Leers: Assert that all expected package manager events are fired during build tests

package_manager/tests/modules/package_manager_test_event_logger/package_manager_test_event_logger.info.yml

+name: 'Package Manager Test Event Logger'
+description: 'Provides an event subscriber to test logging during events in Package Manager'
+type: module
+package: Testing
+dependencies:
+  - automatic_updates:package_manager

package_manager/tests/modules/package_manager_test_event_logger/package_manager_test_event_logger.services.yml

+services:
+  package_manager_test_event_logger.subscriber:
+    class: Drupal\package_manager_test_event_logger\EventSubscriber\EventLogSubscriber
+    tags:
+      - { name: event_subscriber }

package_manager/tests/modules/package_manager_test_event_logger/src/EventSubscriber/EventLogSubscriber.php

+<?php
+
+declare(strict_types = 1);
+
+namespace Drupal\package_manager_test_event_logger\EventSubscriber;
+
+use Drupal\package_manager\Event\PostApplyEvent;
+use Drupal\package_manager\Event\PostCreateEvent;
+use Drupal\package_manager\Event\PostDestroyEvent;
+use Drupal\package_manager\Event\PostRequireEvent;
+use Drupal\package_manager\Event\PreApplyEvent;
+use Drupal\package_manager\Event\PreCreateEvent;
+use Drupal\package_manager\Event\PreDestroyEvent;
+use Drupal\package_manager\Event\PreRequireEvent;
+use Drupal\package_manager\Event\StageEvent;
+use Symfony\Component\EventDispatcher\EventSubscriberInterface;
+
+/**
+ * Defines an event subscriber to test logging during events in Package Manager.
+ */
+final class EventLogSubscriber implements EventSubscriberInterface {
+
+  /**
+   * Logs all events in the stage life cycle.
+   *
+   * @param \Drupal\package_manager\Event\StageEvent $event
+   *   The event object.
+   */
+  public function logEventInfo(StageEvent $event): void {
+    \Drupal::logger('package_manager_test_event_logger')->info('package_manager_test_event_logger-start: Event: ' . get_class($event) . ', Stage instance of: ' . get_class($event->getStage()) . ':package_manager_test_event_logger-end');
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public static function getSubscribedEvents(): array {
+    return [
+      PreCreateEvent::class => ['logEventInfo'],
+      PostCreateEvent::class => ['logEventInfo'],
+      PreRequireEvent::class => ['logEventInfo'],
+      PostRequireEvent::class => ['logEventInfo'],
+      PreApplyEvent::class => ['logEventInfo'],
+      PostApplyEvent::class => ['logEventInfo'],
+      PreDestroyEvent::class => ['logEventInfo'],
+      PostDestroyEvent::class => ['logEventInfo'],
+    ];
+  }
+
+}

package_manager/tests/src/Build/PackageUpdateTest.php

@@ -4,6 +4,8 @@ declare(strict_types = 1);
 
 namespace Drupal\Tests\package_manager\Build;
 
+use Drupal\package_manager\Stage;
+
 /**
  * Tests updating packages in a staging area.
  *
@@ -70,6 +72,8 @@ class PackageUpdateTest extends TemplateProjectTestBase {
     // created this file.
     // @see \Drupal\updated_module\PostApplySubscriber::postApply()
     $this->assertSame('Bravo!', $file_contents['bravo.txt']);
+
+    $this->assertExpectedStageEventsFired(Stage::class);
   }
 
 }

package_manager/tests/src/Build/TemplateProjectTestBase.php

@@ -6,6 +6,14 @@ namespace Drupal\Tests\package_manager\Build;
 
 use Drupal\BuildTests\QuickStart\QuickStartTestBase;
 use Drupal\Composer\Composer;
+use Drupal\package_manager\Event\PostApplyEvent;
+use Drupal\package_manager\Event\PostCreateEvent;
+use Drupal\package_manager\Event\PostDestroyEvent;
+use Drupal\package_manager\Event\PostRequireEvent;
+use Drupal\package_manager\Event\PreApplyEvent;
+use Drupal\package_manager\Event\PreCreateEvent;
+use Drupal\package_manager\Event\PreDestroyEvent;
+use Drupal\package_manager\Event\PreRequireEvent;
 use Drupal\Tests\package_manager\Traits\FixtureUtilityTrait;
 use Drupal\Tests\RandomGeneratorTrait;
 
@@ -293,6 +301,7 @@ END;
     // Install helpful modules.
     $this->installModules([
       'package_manager_test_api',
+      'package_manager_test_event_logger',
       'package_manager_test_release_history',
     ]);
   }
@@ -466,6 +475,67 @@ END;
     return $temp_directory;
   }
 
+  /**
+   * Asserts stage events were fired in a specific order.
+   *
+   * @param string $expected_stage_class
+   *   The expected stage class for the events.
+   * @param array|null $expected_events
+   *   (optional) The expected stage events that should have been fired in the
+   *   order in which they should have been fired. Events can be specified more
+   *   that once if they will be fired multiple times. If there are no events
+   *   specified all life cycle events from PreCreateEvent to PostDestroyEvent
+   *   will be asserted.
+   *
+   * @see \Drupal\package_manager_test_event_logger\EventSubscriber\EventLogSubscriber::logEventInfo
+   */
+  protected function assertExpectedStageEventsFired(string $expected_stage_class, ?array $expected_events = NULL): void {
+    if ($expected_events === NULL) {
+      $expected_events = [
+        PreCreateEvent::class,
+        PostCreateEvent::class,
+        PreRequireEvent::class,
+        PostRequireEvent::class,
+        PreApplyEvent::class,
+        PostApplyEvent::class,
+        PreDestroyEvent::class,
+        PostDestroyEvent::class,
+      ];
+    }
+    else {
+      // The view at 'admin/reports/dblog' currently only shows 50 entries but
+      // this view could be changed to show fewer and our test would not fail.
+      // We need to be sure we are seeing all entries, not just first page.
+      // Since we don't need to log anywhere near 50 entries use 25 to be overly
+      // cautious of the view changing.
+      // @todo Find a better solution than a view that could change to ensure
+      //   ensure these events have fired in https://drupal.org/i/3319768.
+      $this->assertLessThan(25, count($expected_events), 'More than 25 events may not appear on one page of the log view');
+    }
+    $assert_session = $this->getMink()->assertSession();
+    $page = $this->getMink()->getSession()->getPage();
+    $this->visit('/admin/reports/dblog');
+    $assert_session->statusCodeEquals(200);
+    $page->selectFieldOption('Type', 'package_manager_test_event_logger');
+    $page->pressButton('Filter');
+    $assert_session->statusCodeEquals(200);
+
+    // The log entries will not appear completely in the page text but they will
+    // appear in the title attribute of the links.
+    $links = $page->findAll('css', 'a[title^=package_manager_test_event_logger-start]');
+    $actual_titles = [];
+    // Loop through the links in reverse order because the most recent entries
+    // will be first.
+    foreach (array_reverse($links) as $link) {
+      $actual_titles[] = $link->getAttribute('title');
+    }
+    $expected_titles = [];
+    foreach ($expected_events as $event) {
+      $expected_titles[] = "package_manager_test_event_logger-start: Event: $event, Stage instance of: $expected_stage_class:package_manager_test_event_logger-end";
+    }
+    $this->assertSame($expected_titles, $actual_titles);
+  }
+
   // BEGIN: DELETE FROM CORE MERGE REQUEST.
 
   /**

tests/src/Build/CoreUpdateTest.php

@@ -4,7 +4,17 @@ declare(strict_types = 1);
 
 namespace Drupal\Tests\automatic_updates\Build;
 
+use Drupal\automatic_updates\CronUpdater;
+use Drupal\automatic_updates\Updater;
 use Drupal\Composer\Composer;
+use Drupal\package_manager\Event\PostApplyEvent;
+use Drupal\package_manager\Event\PostCreateEvent;
+use Drupal\package_manager\Event\PostDestroyEvent;
+use Drupal\package_manager\Event\PostRequireEvent;
+use Drupal\package_manager\Event\PreApplyEvent;
+use Drupal\package_manager\Event\PreCreateEvent;
+use Drupal\package_manager\Event\PreDestroyEvent;
+use Drupal\package_manager\Event\PreRequireEvent;
 use Drupal\Tests\WebAssert;
 
 /**
@@ -97,13 +107,32 @@ class CoreUpdateTest extends UpdateTestBase {
     $mink = $this->getMink();
     $session = $mink->getSession();
     $session->reload();
-    $mink->assertSession()->statusCodeEquals(200);
+    $update_status_code = $session->getStatusCode();
     $file_contents = $session->getPage()->getContent();
-    $file_contents = json_decode($file_contents, TRUE, 512, JSON_THROW_ON_ERROR);
-    $this->assertStringContainsString("const VERSION = '9.8.1';", $file_contents['web/core/lib/Drupal.php']);
+    $this->assertExpectedStageEventsFired(
+      Updater::class,
+      [
+        // ::assertReadOnlyFileSystemError attempts to start an update
+        // multiple times so 'PreCreateEvent' will be fired multiple times.
+        // @see \Drupal\Tests\automatic_updates\Build\CoreUpdateTest::assertReadOnlyFileSystemError()
+        PreCreateEvent::class,
+        PreCreateEvent::class,
+        PreCreateEvent::class,
+        PostCreateEvent::class,
+        PreRequireEvent::class,
+        PostRequireEvent::class,
+        PreApplyEvent::class,
+        PostApplyEvent::class,
+        PreDestroyEvent::class,
+        PostDestroyEvent::class,
+      ]
+    );
     // Even though the response is what we expect, assert the status code as
     // well, to be extra-certain that there was no kind of server-side error.
+    $this->assertSame(200, $update_status_code);
+    $file_contents = json_decode($file_contents, TRUE, 512, JSON_THROW_ON_ERROR);
 
+    $this->assertStringContainsString("const VERSION = '9.8.1';", $file_contents['web/core/lib/Drupal.php']);
     $this->assertUpdateSuccessful('9.8.1');
   }
 
@@ -134,6 +163,7 @@ class CoreUpdateTest extends UpdateTestBase {
     $page->pressButton('Continue');
     $this->waitForBatchJob();
     $assert_session->pageTextContains('Update complete!');
+    $this->assertExpectedStageEventsFired(Updater::class);
     $assert_session->pageTextNotContains('There is a security update available for your version of Drupal.');
     $this->assertUpdateSuccessful('9.8.1');
   }
@@ -164,7 +194,9 @@ class CoreUpdateTest extends UpdateTestBase {
 
     $assert_session->pageTextContains('Your site is ready for automatic updates.');
     $page->clickLink('Run cron');
-    $assert_session->statusCodeEquals(200);
+    $cron_run_status_code = $mink->getSession()->getStatusCode();
+    $this->assertExpectedStageEventsFired(CronUpdater::class);
+    $this->assertSame(200, $cron_run_status_code);
 
     // There should be log messages, but no errors or warnings should have been
     // logged by Automatic Updates.