diff --git a/package_manager/src/StageBase.php b/package_manager/src/StageBase.php
index 38730264e467dc4db9460ab71b3fc63a202293af..04475d9b1f01a913c6b5220316c94d8f30bebc52 100644
--- a/package_manager/src/StageBase.php
+++ b/package_manager/src/StageBase.php
@@ -578,6 +578,8 @@ abstract class StageBase implements LoggerAwareInterface {
}
if (isset($error)) {
+ // Ensure the error is logged for post-mortem diagnostics.
+ Error::logException($this->logger, $error);
if ($on_error) {
$on_error();
}
diff --git a/package_manager/tests/src/Kernel/StageBaseTest.php b/package_manager/tests/src/Kernel/StageBaseTest.php
index 66702968afaac422c5cb508da010e3d05e5be5f4..90681408c3aecfdd9609ee63b3c58df5ab6c9b4f 100644
--- a/package_manager/tests/src/Kernel/StageBaseTest.php
+++ b/package_manager/tests/src/Kernel/StageBaseTest.php
@@ -10,10 +10,14 @@ use Drupal\Core\Extension\ModuleUninstallValidatorException;
use Drupal\Core\StringTranslation\TranslatableMarkup;
use Drupal\package_manager\Event\CollectPathsToExcludeEvent;
use Drupal\package_manager\Event\PostApplyEvent;
+use Drupal\package_manager\Event\PostCreateEvent;
+use Drupal\package_manager\Event\PostRequireEvent;
use Drupal\package_manager\Event\PreApplyEvent;
use Drupal\package_manager\Event\PreCreateEvent;
+use Drupal\package_manager\Event\PreRequireEvent;
use Drupal\package_manager\Event\StageEvent;
use Drupal\package_manager\Exception\ApplyFailedException;
+use Drupal\package_manager\Exception\StageEventException;
use Drupal\package_manager\Exception\StageException;
use Drupal\package_manager\Exception\StageFailureMarkerException;
use Drupal\package_manager\FailureMarker;
@@ -22,6 +26,7 @@ use Drupal\package_manager\Validator\WritableFileSystemValidator;
use Drupal\package_manager_bypass\LoggingBeginner;
use Drupal\package_manager_bypass\LoggingCommitter;
use Drupal\package_manager_bypass\NoOpStager;
+use Drupal\package_manager_test_validation\EventSubscriber\TestSubscriber;
use PhpTuf\ComposerStager\API\Core\BeginnerInterface;
use PhpTuf\ComposerStager\API\Core\CommitterInterface;
use PhpTuf\ComposerStager\API\Core\StagerInterface;
@@ -60,6 +65,57 @@ class StageBaseTest extends PackageManagerKernelTestBase {
$container->getDefinition('event_dispatcher')->addTag('persist');
}
+ /**
+ * Data provider for testLoggedOnError().
+ *
+ * @return string[][]
+ * The test cases.
+ */
+ public function providerLoggedOnError(): array {
+ return [
+ [PreCreateEvent::class],
+ [PostCreateEvent::class],
+ [PreRequireEvent::class],
+ [PostRequireEvent::class],
+ [PreApplyEvent::class],
+ [PostApplyEvent::class],
+ ];
+ }
+
+ /**
+ * @covers \Drupal\package_manager\StageBase::dispatch
+ *
+ * @dataProvider providerLoggedOnError
+ *
+ * @param string $event_class
+ * The event class to throw an exception on.
+ */
+ public function testLoggedOnError(string $event_class): void {
+ $exception = new \Exception("This should be logged!");
+ TestSubscriber::setException($exception, $event_class);
+
+ $stage = $this->createStage();
+ $logger = new TestLogger();
+ $stage->setLogger($logger);
+
+ try {
+ $stage->create();
+ $stage->require(['drupal/core:9.8.1']);
+ $stage->apply();
+ $stage->postApply();
+ $this->fail('Expected an exception to be thrown, but none was.');
+ }
+ catch (StageEventException $e) {
+ $this->assertInstanceOf($event_class, $e->event);
+
+ $predicate = function (array $record) use ($e): bool {
+ $context = $record['context'];
+ return $context['@message'] === $e->getMessage() && str_contains($context['@backtrace_string'], 'testLoggedOnError');
+ };
+ $this->assertTrue($logger->hasRecordThatPasses($predicate, LogLevel::ERROR));
+ }
+ }
+
/**
* @covers ::getMetadata
* @covers ::setMetadata
diff --git a/src/ConsoleUpdateStage.php b/src/ConsoleUpdateStage.php
index f8cfe9c676c01316b7fec92f83cbe4722ad79a0e..0256328141bf8aeaadb7053aeca52e7ea83d41d4 100644
--- a/src/ConsoleUpdateStage.php
+++ b/src/ConsoleUpdateStage.php
@@ -11,6 +11,7 @@ use Drupal\Core\Queue\QueueFactory;
use Drupal\Core\TempStore\SharedTempStoreFactory;
use Drupal\Core\Url;
use Drupal\package_manager\ComposerInspector;
+use Drupal\package_manager\Error;
use Drupal\package_manager\Event\PreCreateEvent;
use Drupal\package_manager\Exception\ApplyFailedException;
use Drupal\package_manager\Exception\StageEventException;
@@ -209,11 +210,19 @@ class ConsoleUpdateStage extends UpdateStage {
}
catch (\Throwable $e) {
$this->lock->release('cron');
+
if ($e instanceof StageEventException && $e->event instanceof PreCreateEvent) {
// If the error happened during PreCreateEvent then the update did not
// really start.
$update_started = FALSE;
}
+ // Validation errors, or exceptions thrown by stage life cycle event
+ // listeners, were already logged by ::dispatch(), but we need to log
+ // exceptions that don't fall into those categories.
+ if (!$e instanceof StageEventException) {
+ Error::logException($this->logger, $e);
+ }
+
// Send notifications about the failed update.
$mail_params = [
'previous_version' => $installed_version,
@@ -241,7 +250,6 @@ class ConsoleUpdateStage extends UpdateStage {
foreach ($this->statusCheckMailer->getRecipients() as $email => $langcode) {
$this->mailManager->mail('automatic_updates', $key, $email, $langcode, $mail_params);
}
- $this->logger->error($e->getMessage());
// If an error occurred during the pre-create event, the stage will be
// marked as available and we shouldn't try to destroy it, since the stage
@@ -314,8 +322,12 @@ class ConsoleUpdateStage extends UpdateStage {
try {
$this->postApply();
}
+ catch (StageEventException) {
+ // Validation errors, or exceptions caused by stage life cycle events,
+ // were already logged by ::dispatch().
+ }
catch (\Throwable $e) {
- $this->logger->error($e->getMessage());
+ Error::logException($this->logger, $e);
}
$this->lock->release('cron');
$this->destroy();
diff --git a/tests/src/Kernel/AutomaticUpdatesKernelTestBase.php b/tests/src/Kernel/AutomaticUpdatesKernelTestBase.php
index 031fc24dd1d27fc9341a6c1498563607e630e5ea..39819ac16ce2208f33d739660121ce7edc24b212 100644
--- a/tests/src/Kernel/AutomaticUpdatesKernelTestBase.php
+++ b/tests/src/Kernel/AutomaticUpdatesKernelTestBase.php
@@ -4,9 +4,11 @@ declare(strict_types = 1);
namespace Drupal\Tests\automatic_updates\Kernel;
+use ColinODell\PsrTestLogger\TestLogger;
use Drupal\automatic_updates\CronUpdateRunner;
use Drupal\automatic_updates\ConsoleUpdateStage;
use Drupal\Core\DependencyInjection\ContainerBuilder;
+use Drupal\Core\Logger\RfcLogLevel;
use Drupal\package_manager\Validator\SymlinkValidator;
use Drupal\package_manager\Validator\WritableFileSystemValidator;
use Drupal\Tests\automatic_updates\Traits\ValidationTestTrait;
@@ -103,6 +105,19 @@ abstract class AutomaticUpdatesKernelTestBase extends PackageManagerKernelTestBa
$this->container->get(ConsoleUpdateStage::class)->performUpdate();
}
+ /**
+ * Asserts that an exception containing a particular message was logged.
+ *
+ * @param string $message
+ * The message that should have been logged.
+ * @param \ColinODell\PsrTestLogger\TestLogger $logger
+ * The logger.
+ */
+ protected function assertExceptionLogged(string $message, TestLogger $logger): void {
+ $predicate = fn ($record) => str_contains($record['context']['@message'] ?? '', $message);
+ $this->assertTrue($logger->hasRecordThatPasses($predicate, RfcLogLevel::ERROR));
+ }
+
}
/**
diff --git a/tests/src/Kernel/ConsoleUpdateStageTest.php b/tests/src/Kernel/ConsoleUpdateStageTest.php
index 7761b5f190d1020c3a3870f32f145c8cc777bd1e..7ba670674b91ad66746e85affea9909a0192c974 100644
--- a/tests/src/Kernel/ConsoleUpdateStageTest.php
+++ b/tests/src/Kernel/ConsoleUpdateStageTest.php
@@ -90,7 +90,7 @@ class ConsoleUpdateStageTest extends AutomaticUpdatesKernelTestBase {
$this->runConsoleUpdateStage();
$this->assertNoCronRun();
- $this->assertTrue($this->logger->hasRecord($exception->getMessage(), (string) RfcLogLevel::ERROR));
+ $this->assertExceptionLogged($exception->getMessage(), $this->logger);
// Ensure we sent a success email to all recipients, even though post-apply
// tasks failed.
@@ -326,10 +326,8 @@ END;
$this->assertTrue($stage->isAvailable());
$this->runConsoleUpdateStage();
- $logged_by_stage = $this->logger->hasRecord($exception->getMessage(), (string) RfcLogLevel::ERROR);
-
$this->assertTrue($stage->isAvailable());
- $this->assertTrue($logged_by_stage);
+ $this->assertExceptionLogged($exception->getMessage(), $this->logger);
$this->assertEmpty($cron_logger->records);
}
@@ -695,7 +693,7 @@ END;
$this->addEventTestListener($listener, PostCreateEvent::class);
$lock_checked_on_events = [];
$this->runConsoleUpdateStage();
- $this->assertTrue($this->logger->hasRecordThatContains('Nope!', RfcLogLevel::ERROR));
+ $this->assertExceptionLogged('Nope!', $this->logger);
$this->assertTrue($lock->lockMayBeAvailable('cron'));
$this->assertSame([PreCreateEvent::class], $lock_checked_on_events);
}
diff --git a/tests/src/Kernel/StatusCheck/PhpExtensionsValidatorTest.php b/tests/src/Kernel/StatusCheck/PhpExtensionsValidatorTest.php
index 7552a8d91f86792234c5f09983d5fceef3471604..74c063dbfb6837e4c38925778a7f1b0ac9ce9c9a 100644
--- a/tests/src/Kernel/StatusCheck/PhpExtensionsValidatorTest.php
+++ b/tests/src/Kernel/StatusCheck/PhpExtensionsValidatorTest.php
@@ -5,7 +5,6 @@ declare(strict_types = 1);
namespace Drupal\Tests\automatic_updates\Kernel\StatusCheck;
use Drupal\automatic_updates\CronUpdateRunner;
-use Drupal\Core\Logger\RfcLogLevel;
use Drupal\package_manager\ValidationResult;
use Drupal\Tests\automatic_updates\Kernel\AutomaticUpdatesKernelTestBase;
use Drupal\Tests\package_manager\Traits\PackageManagerBypassTestTrait;
@@ -64,7 +63,7 @@ class PhpExtensionsValidatorTest extends AutomaticUpdatesKernelTestBase {
$this->runConsoleUpdateStage();
// The update should have been stopped before it started.
$this->assertUpdateStagedTimes(0);
- $this->assertTrue($logger->hasRecordThatContains((string) $error_result->messages[0], RfcLogLevel::ERROR));
+ $this->assertExceptionLogged((string) $error_result->messages[0], $logger);
}
/**
@@ -88,7 +87,7 @@ class PhpExtensionsValidatorTest extends AutomaticUpdatesKernelTestBase {
$this->runConsoleUpdateStage();
// The update should have been staged, but then stopped with an error.
$this->assertUpdateStagedTimes(1);
- $this->assertTrue($logger->hasRecordThatContains("Unattended updates are not allowed while Xdebug is enabled. You cannot receive updates, including security updates, until it is disabled.", RfcLogLevel::ERROR));
+ $this->assertExceptionLogged("Unattended updates are not allowed while Xdebug is enabled. You cannot receive updates, including security updates, until it is disabled.", $logger);
}
/**
diff --git a/tests/src/Kernel/StatusCheck/StagedDatabaseUpdateValidatorTest.php b/tests/src/Kernel/StatusCheck/StagedDatabaseUpdateValidatorTest.php
index d4b3368541d60da8555bb6b6231355c5429fbdb8..b648cdf9be5d325bbb13cccb9b006732a7e0887e 100644
--- a/tests/src/Kernel/StatusCheck/StagedDatabaseUpdateValidatorTest.php
+++ b/tests/src/Kernel/StatusCheck/StagedDatabaseUpdateValidatorTest.php
@@ -4,7 +4,6 @@ declare(strict_types = 1);
namespace Drupal\Tests\automatic_updates\Kernel\StatusCheck;
-use Drupal\Core\Logger\RfcLogLevel;
use Drupal\package_manager\Event\PreApplyEvent;
use Drupal\Tests\automatic_updates\Kernel\AutomaticUpdatesKernelTestBase;
use ColinODell\PsrTestLogger\TestLogger;
@@ -39,8 +38,7 @@ class StagedDatabaseUpdateValidatorTest extends AutomaticUpdatesKernelTestBase {
$this->addEventTestListener($listener);
$this->runConsoleUpdateStage();
- $expected_message = "The update cannot proceed because database updates have been detected in the following extensions.\nSystem\n";
- $this->assertTrue($logger->hasRecord($expected_message, (string) RfcLogLevel::ERROR));
+ $this->assertExceptionLogged("The update cannot proceed because database updates have been detected in the following extensions.\nSystem\n", $logger);
}
}
diff --git a/tests/src/Kernel/StatusCheck/WindowsValidatorTest.php b/tests/src/Kernel/StatusCheck/WindowsValidatorTest.php
index e159a567c3f9bcc77d1da3ac329e7719cc39d9f4..9378908c29dc01f762a8b415150d8b324cd68115 100644
--- a/tests/src/Kernel/StatusCheck/WindowsValidatorTest.php
+++ b/tests/src/Kernel/StatusCheck/WindowsValidatorTest.php
@@ -135,7 +135,7 @@ class WindowsValidatorTest extends AutomaticUpdatesKernelTestBase {
$this->runConsoleUpdateStage();
foreach ($expected_results as $result) {
foreach ($result->messages as $message) {
- $this->assertTrue($logger->hasRecordThatContains((string) $message, RfcLogLevel::ERROR));
+ $this->assertExceptionLogged((string) $message, $logger);
}
}