Problem/Motivation

In #3357969: For web server dependent unattended updates run the entire life cycle in a separate process that will not be affected by hosting time limits I am separating background updates from Automated Cron.

If that issue is success and gets committed we can just close this issue.

If we decide we cannot do #3357969 then some stuff I learned there still made me realize that we missing test coverage. In that issue I am trying to do updates in Kernel Terminate event, which is what Automated Cron uses and it seems to be very tricky. This made realize we don't actually test using automated cron. We test by clicking "Run cron" which does not run the update during the kernel terminate event.

Steps to reproduce

Proposed resolution

If #3357969: For web server dependent unattended updates run the entire life cycle in a separate process that will not be affected by hosting time limits get committed close this issue as we will not be using cron.

If that issue does not get committed create the test coverage.

Remaining tasks

User interface changes

API changes

Data model changes

Issue fork automatic_updates-3362978

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

About issue forks

Comments

tedbow created an issue. See original summary.

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented
Priority: Normal » Major

Changing to major because if end up still relying on cron this major missing test coverage

tedbow opened merge request !890

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented
Title: [PP-1] Create a test to ensure the module works with automated cron » Module does not work with Automated Cron
Status: Postponed » Active
Related issues: +#3181946: ReplicaKillSwitch unnecessarily starts a session on each request

un-Postponing because I have a test that think proves it does not work.

Not sure why yet but I think #3357969: For web server dependent unattended updates run the entire life cycle in a separate process that will not be affected by hosting time limits will be affected also unless we don't switch to the anonymous user when performing the update which is what Cron does.

I think it is combo of \Drupal\Core\Cron switching to the anonymous user and \Drupal\automated_cron\EventSubscriber\AutomatedCron running in KernelEvents::TERMINATE

this core issue may be related #3181946: ReplicaKillSwitch unnecessarily starts a session on each request

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented
Priority: Major » Critical
Status: Active » Needs work

I tried the patch in #3181946 and did not fix it

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented
Assigned: Unassigned » wim leers
Issue tags: +sprint
wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

I went very deep in debugging this. Could not figure it out so far

https://symfony.com/doc/current/components/http_kernel.html#component-ht... does not indicate this should not work.

Eventually, after ~1.5h of debugging at ever deeper levels, I tried to find existing test coverage for Automated Cron to see if that at least works. There's only one test: \Drupal\Tests\system\Functional\System\CronRunTest::testAutomatedCron()

Turns out that ALSO FAILS 🤪

Testing /Users/wim.leers/core/core/modules/system/tests/src/Functional/System
F                                                                   1 / 1 (100%)

Time: 00:05.895, Memory: 10.00 MB

There was 1 failure:

1) Drupal\Tests\system\Functional\System\CronRunTest::testAutomatedCron
Failed asserting that 1685454718 is less than 1685454718.

👆 That does not execute cron at all!

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented
Assigned: wim leers » Unassigned
Issue tags: -sprint
Related issues: +#2941687: Subrequests in an KernelEvents::TERMINATE event subscriber (f.e. cron tasks doing subrequests) try to restart a session, resulting in runtime exceptions

I previously debugged this problem >4 years ago: #2941687-19: Subrequests in an KernelEvents::TERMINATE event subscriber (f.e. cron tasks doing subrequests) try to restart a session, resulting in runtime exceptions. 😬🤣

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

After a lot of debugging, the culprit is:

$stage = \Drupal::service('automatic_updates.cron_update_stage');

in automatic_updates_cron(). During construction of that service, it calls \Drupal\Core\TempStore\SharedTempStoreFactory::get(), which in turn eventually calls \Drupal\Core\TempStore\SharedTempStore::ensureAnonymousSession().

That is what triggers the session.

We can fix that by adding an optional ?string $owner = NULL to StageBase and UpdateStage, and having CronUpdateStage hardcode that to 'cron' as the owner.

BUT! Fixing that is not enough!

Because automatic_updates_cron() also does:

$status_checker = \Drupal::service('automatic_updates.status_checker');

… which happens to need these services during construction:

  public function __construct(
    KeyValueExpirableFactoryInterface $key_value_expirable_factory,
    private readonly TimeInterface $time,
    private readonly EventDispatcherInterface $eventDispatcher,
    private readonly UpdateStage $updateStage,
    private readonly CronUpdateStage $cronUpdateStage,
    private readonly int $resultsTimeToLive,
  ) {

… we still end up calling UpdateStage's construction, which still has a NULL owner, and hence still starts the session 🙃

P.S.: note that \Drupal\Core\Cron::run() specifically has logic around this:

    // Force the current user to anonymous to ensure consistent permissions on
    // cron runs.
    $this->accountSwitcher->switchTo(new AnonymousUserSession());

…

    // Restore the user.
    $this->accountSwitcher->switchBack();
wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented
Assigned: Unassigned » wim leers

Same exact test failure output.

But apply

diff --git a/core/lib/Drupal/Core/Cron.php b/core/lib/Drupal/Core/Cron.php
index 1463943415..94c0d41b84 100644
--- a/core/lib/Drupal/Core/Cron.php
+++ b/core/lib/Drupal/Core/Cron.php
@@ -336,6 +336,7 @@ protected function invokeCronHandlers() {
       }
       catch (\Exception $e) {
         Error::logException($this->logger, $e);
+        $logger->error($e->getTraceAsString());
       }
 
       Timer::stop('cron_' . $module);

and you'll see that the problem went from

PHPUnit 9.5.28 by Sebastian Bergmann and contributors.

Testing /Users/wim.leers/core/modules/contrib/automatic_updates/tests/src/Functional
F                                                                   1 / 1 (100%)

Time: 00:09.878, Memory: 10.00 MB

There was 1 failure:

1) Drupal\Tests\automatic_updates\Functional\AutomatedCronIntegrationTest::testAutomatedCronUpdate
Failed asserting that two arrays are identical.
--- Expected
+++ Actual
@@ @@
-Array &0 ()
+Array &0 (
+    0 => '<em class="placeholder">RuntimeException</em>: Failed to start the session because headers have already been sent by "/Users/wim.leers/core/vendor/symfony/http-foundation/Response.php" at line 1279. in <em class="placeholder">Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->start()</em> (line <em class="placeholder">132</em> of <em class="placeholder">/Users/wim.leers/core/vendor/symfony/http-foundation/Session/Storage/NativeSessionStorage.php</em>).'
+    1 => '#0 /Users/wim.leers/core/core/lib/Drupal/Core/Session/SessionManager.php(144): Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->start()\n
+#1 /Users/wim.leers/core/core/lib/Drupal/Core/Session/SessionManager.php(109): Drupal\Core\Session\SessionManager->startNow()\n
+#2 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Storage/NativeSessionStorage.php(296): Drupal\Core\Session\SessionManager->start()\n
+#3 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(201): Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->getBag('attributes')\n
+#4 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(221): Symfony\Component\HttpFoundation\Session\Session->getBag('attributes')\n
+#5 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(69): Symfony\Component\HttpFoundation\Session\Session->getAttributeBag()\n
+#6 /Users/wim.leers/core/core/lib/Drupal/Core/TempStore/SharedTempStoreFactory.php(97): Symfony\Component\HttpFoundation\Session\Session->get('core.tempstore....', 'LR5YuzxxVYMSqS3...')\n
+#7 /Users/wim.leers/core/modules/contrib/automatic_updates/package_manager/src/StageBase.php(200): Drupal\Core\TempStore\SharedTempStoreFactory->get('package_manager...')\n
+#8 /Users/wim.leers/core/modules/contrib/automatic_updates/src/UpdateStage.php(75): Drupal\package_manager\StageBase->__construct(Object(Drupal\package_manager_bypass\MockPathLocator), Object(Drupal\package_manager_bypass\LoggingBeginner), Object(Drupal\package_manager_bypass\NoOpStager), Object(Drupal\package_manager_bypass\LoggingCommitter), Object(Drupal\Core\File\FileSystem), Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher), Object(Drupal\Core\TempStore\SharedTempStoreFactory), Object(Drupal\update_test\Datetime\TestTime), Object(PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory), Object(Drupal\package_manager\FailureMarker))\n
+#9 /Users/wim.leers/core/modules/contrib/automatic_updates/src/CronUpdateStage.php(115): Drupal\automatic_updates\UpdateStage->__construct(Object(Drupal\package_manager\ComposerInspector), Object(Drupal\package_manager_bypass\MockPathLocator), Object(Drupal\package_manager_bypass\LoggingBeginner), Object(Drupal\package_manager_bypass\NoOpStager), Object(Drupal\package_manager_bypass\LoggingCommitter), Object(Drupal\Core\File\FileSystem), Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher), Object(Drupal\Core\TempStore\SharedTempStoreFactory), Object(Drupal\update_test\Datetime\TestTime), Object(PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory), Object(Drupal\package_manager\FailureMarker))\n
+#10 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(259): Drupal\automatic_updates\CronUpdateStage->__construct(Object(Drupal\automatic_updates\ReleaseChooser), Object(Drupal\Core\Mail\MailManager), Object(Drupal\automatic_updates\StatusCheckMailer), Object(Drupal\Core\State\State), Object(Drupal\Core\Config\ConfigFactory), Object(Drupal\package_manager\ComposerInspector), Object(Drupal\package_manager_bypass\MockPathLocator), Object(Drupal\package_manager_bypass\LoggingBeginner), Object(Drupal\package_manager_bypass\NoOpStager), Object(Drupal\package_manager_bypass\LoggingCommitter), Object(Drupal\Core\File\FileSystem), Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher), Object(Drupal\Core\TempStore\SharedTempStoreFactory), Object(Drupal\update_test\Datetime\TestTime), Object(PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory), Object(Drupal\package_manager\FailureMarker))\n
+#11 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(177): Drupal\Component\DependencyInjection\Container->createService(Array, 'automatic_updat...')\n
+#12 /Users/wim.leers/core/core/lib/Drupal.php(197): Drupal\Component\DependencyInjection\Container->get('automatic_updat...')\n
+#13 /Users/wim.leers/core/modules/contrib/automatic_updates/automatic_updates.module(173): Drupal::service('automatic_updat...')\n
+#14 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(335): automatic_updates_cron()\n
+#15 /Users/wim.leers/core/core/lib/Drupal/Core/Extension/ModuleHandler.php(388): Drupal\Core\Cron->Drupal\Core\@closure(Object(Closure), 'automatic_updat...')\n
+#16 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(344): Drupal\Core\Extension\ModuleHandler->invokeAllWith('cron', Object(Closure))\n
+#17 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(159): Drupal\Core\Cron->invokeCronHandlers()\n
+#18 /Users/wim.leers/core/core/lib/Drupal/Core/ProxyClass/Cron.php(75): Drupal\Core\Cron->run()\n
+#19 /Users/wim.leers/core/core/modules/automated_cron/src/EventSubscriber/AutomatedCron.php(65): Drupal\Core\ProxyClass\Cron->run()\n
+#20 [internal function]: Drupal\automated_cron\EventSubscriber\AutomatedCron->onTerminate(Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...', Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher))\n
+#21 /Users/wim.leers/core/core/lib/Drupal/Component/EventDispatcher/ContainerAwareEventDispatcher.php(111): call_user_func(Array, Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...', Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher))\n
+#22 /Users/wim.leers/core/vendor/symfony/http-kernel/HttpKernel.php(97): Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher->dispatch(Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...')\n
+#23 /Users/wim.leers/core/core/lib/Drupal/Core/StackMiddleware/StackedHttpKernel.php(63): Symfony\Component\HttpKernel\HttpKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#24 /Users/wim.leers/core/core/lib/Drupal/Core/DrupalKernel.php(688): Drupal\Core\StackMiddleware\StackedHttpKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#25 /Users/wim.leers/core/index.php(22): Drupal\Core\DrupalKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#26 @main'
+)

/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/Constraint/IsIdentical.php:79
/Users/wim.leers/core/modules/contrib/automatic_updates/tests/src/Functional/AutomatedCronIntegrationTest.php:61
/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/TestResult.php:728

FAILURES!
Tests: 1, Assertions: 11, Failures: 1.
Process finished with exit code 1

change to

PHPUnit 9.5.28 by Sebastian Bergmann and contributors.

Testing /Users/wim.leers/core/modules/contrib/automatic_updates/tests/src/Functional
F                                                                   1 / 1 (100%)

Time: 00:10.175, Memory: 10.00 MB

There was 1 failure:

1) Drupal\Tests\automatic_updates\Functional\AutomatedCronIntegrationTest::testAutomatedCronUpdate
Failed asserting that two arrays are identical.
--- Expected
+++ Actual
@@ @@
-Array &0 ()
+Array &0 (
+    0 => '<em class="placeholder">RuntimeException</em>: Failed to start the session because headers have already been sent by &quot;/Users/wim.leers/core/vendor/symfony/http-foundation/Response.php&quot; at line 1279. in <em class="placeholder">Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage-&gt;start()</em> (line <em class="placeholder">132</em> of <em class="placeholder">/Users/wim.leers/core/vendor/symfony/http-foundation/Session/Storage/NativeSessionStorage.php</em>).'
+    1 => '#0 /Users/wim.leers/core/core/lib/Drupal/Core/Session/SessionManager.php(144): Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->start()\n
+#1 /Users/wim.leers/core/core/lib/Drupal/Core/Session/SessionManager.php(109): Drupal\Core\Session\SessionManager->startNow()\n
+#2 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Storage/NativeSessionStorage.php(296): Drupal\Core\Session\SessionManager->start()\n
+#3 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(201): Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->getBag('attributes')\n
+#4 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(221): Symfony\Component\HttpFoundation\Session\Session->getBag('attributes')\n
+#5 /Users/wim.leers/core/vendor/symfony/http-foundation/Session/Session.php(69): Symfony\Component\HttpFoundation\Session\Session->getAttributeBag()\n
+#6 /Users/wim.leers/core/core/lib/Drupal/Core/TempStore/SharedTempStoreFactory.php(97): Symfony\Component\HttpFoundation\Session\Session->get('core.tempstore....', 'AL1Nlj4QDlEdzyy...')\n
+#7 /Users/wim.leers/core/modules/contrib/automatic_updates/package_manager/src/StageBase.php(203): Drupal\Core\TempStore\SharedTempStoreFactory->get('package_manager...', 'AL1Nlj4QDlEdzyy...')\n
+#8 /Users/wim.leers/core/modules/contrib/automatic_updates/src/UpdateStage.php(78): Drupal\package_manager\StageBase->__construct(Object(Drupal\package_manager_bypass\MockPathLocator), Object(Drupal\package_manager_bypass\LoggingBeginner), Object(Drupal\package_manager_bypass\NoOpStager), Object(Drupal\package_manager_bypass\LoggingCommitter), Object(Drupal\Core\File\FileSystem), Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher), Object(Drupal\Core\TempStore\SharedTempStoreFactory), Object(Drupal\update_test\Datetime\TestTime), Object(PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory), Object(Drupal\package_manager\FailureMarker), NULL)\n
+#9 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(259): Drupal\automatic_updates\UpdateStage->__construct(Object(Drupal\package_manager\ComposerInspector), Object(Drupal\package_manager_bypass\MockPathLocator), Object(Drupal\package_manager_bypass\LoggingBeginner), Object(Drupal\package_manager_bypass\NoOpStager), Object(Drupal\package_manager_bypass\LoggingCommitter), Object(Drupal\Core\File\FileSystem), Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher), Object(Drupal\Core\TempStore\SharedTempStoreFactory), Object(Drupal\update_test\Datetime\TestTime), Object(PhpTuf\ComposerStager\Infrastructure\Factory\Path\PathFactory), Object(Drupal\package_manager\FailureMarker))\n
+#10 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(177): Drupal\Component\DependencyInjection\Container->createService(Array, 'automatic_updat...')\n
+#11 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(440): Drupal\Component\DependencyInjection\Container->get('automatic_updat...', 1)\n
+#12 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(237): Drupal\Component\DependencyInjection\Container->resolveServicesAndParameters(Array)\n
+#13 /Users/wim.leers/core/core/lib/Drupal/Component/DependencyInjection/Container.php(177): Drupal\Component\DependencyInjection\Container->createService(Array, 'automatic_updat...')\n
+#14 /Users/wim.leers/core/core/lib/Drupal.php(197): Drupal\Component\DependencyInjection\Container->get('automatic_updat...')\n
+#15 /Users/wim.leers/core/modules/contrib/automatic_updates/automatic_updates.module(177): Drupal::service('automatic_updat...')\n
+#16 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(335): automatic_updates_cron()\n
+#17 /Users/wim.leers/core/core/lib/Drupal/Core/Extension/ModuleHandler.php(388): Drupal\Core\Cron->Drupal\Core\@closure(Object(Closure), 'automatic_updat...')\n
+#18 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(344): Drupal\Core\Extension\ModuleHandler->invokeAllWith('cron', Object(Closure))\n
+#19 /Users/wim.leers/core/core/lib/Drupal/Core/Cron.php(159): Drupal\Core\Cron->invokeCronHandlers()\n
+#20 /Users/wim.leers/core/core/lib/Drupal/Core/ProxyClass/Cron.php(75): Drupal\Core\Cron->run()\n
+#21 /Users/wim.leers/core/core/modules/automated_cron/src/EventSubscriber/AutomatedCron.php(65): Drupal\Core\ProxyClass\Cron->run()\n
+#22 [internal function]: Drupal\automated_cron\EventSubscriber\AutomatedCron->onTerminate(Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...', Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher))\n
+#23 /Users/wim.leers/core/core/lib/Drupal/Component/EventDispatcher/ContainerAwareEventDispatcher.php(111): call_user_func(Array, Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...', Object(Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher))\n
+#24 /Users/wim.leers/core/vendor/symfony/http-kernel/HttpKernel.php(97): Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher->dispatch(Object(Symfony\Component\HttpKernel\Event\TerminateEvent), 'kernel.terminat...')\n
+#25 /Users/wim.leers/core/core/lib/Drupal/Core/StackMiddleware/StackedHttpKernel.php(63): Symfony\Component\HttpKernel\HttpKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#26 /Users/wim.leers/core/core/lib/Drupal/Core/DrupalKernel.php(688): Drupal\Core\StackMiddleware\StackedHttpKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#27 /Users/wim.leers/core/index.php(22): Drupal\Core\DrupalKernel->terminate(Object(Symfony\Component\HttpFoundation\Request), Object(Drupal\Core\Routing\LocalRedirectResponse))\n
+#28 @main'
+)

/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/Constraint/IsIdentical.php:79
/Users/wim.leers/core/modules/contrib/automatic_updates/tests/src/Functional/AutomatedCronIntegrationTest.php:61
/Users/wim.leers/core/vendor/phpunit/phpunit/src/Framework/TestResult.php:728

FAILURES!
Tests: 1, Assertions: 11, Failures: 1.
Process finished with exit code 1

The first difference (earliest in the stack):

- #13 /Users/wim.leers/core/modules/contrib/automatic_updates/automatic_updates.module(173): Drupal::service('automatic_updat...')\n
+#15 /Users/wim.leers/core/modules/contrib/automatic_updates/automatic_updates.module(177): Drupal::service('automatic_updat...')\n

→ changes from line 173 to line 177, in a file which my commit a620b00f didn't touch!

Line 173:

$stage = \Drupal::service('automatic_updates.cron_update_stage');

Line 177:

$status_checker = \Drupal::service('automatic_updates.status_checker');

👆 This proves that I did fix the original problem!

Let's see if I can fix this problem too…

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

hook_modules_installed() triggered the above problem too. Worked around that in 488dac69.

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

After those 3 commits, I now have an actually meaningful error message in the output:

+    7 => '[automatic_updates 3] The requested update to 'drupal/core-recommended' to version '9.8.2' does not match the actual staged update to '9.8.1'.\n
+The requested update to 'drupal/core-dev' to version '9.8.2' does not match the actual staged update to '9.8.1'.\n

… which makes sense because that's what \Drupal\Tests\automatic_updates\Functional\AutomaticUpdatesFunctionalTestBase::installModulesFromClassProperty() pretends is the latest security release …

… which AFAICT means this test was wrong all along? 😅 But it still revealed genuine bugs though!

The reason behind commit 030809aa:

Even if one disables the whole status checker thing (as shown in #10 to definitely cause some problems), it STILL fails. Because \Drupal\package_manager\StageBase::create() is doing:

    // Re-acquire the tempstore to ensure that the lock is written by whoever is
    // actually logged in (or not) right now, since it's possible that the stage
    // was instantiated (i.e., __construct() was called) by a different session,
    // which would result in the lock having the wrong owner and the stage not
    // being claimable by whoever is actually creating it.
    $this->tempStore = $this->tempStoreFactory->get('package_manager_stage');
    $this->tempStore->set(static::TEMPSTORE_LOCK_KEY, [$id, static::class]);

which means we AGAIN call \Drupal\Core\TempStore\SharedTempStoreFactory::get() without $owner.

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented
Assigned: wim leers » Unassigned

I've run out of steam.

Notes of what I have not been able to figure out:

  1. why PHPStorm/XDebug now refuse to break on index.php in the request (</code>) that <code>\Drupal\Tests\automatic_updates\Functional\AutomatedCronIntegrationTest::testAutomatedCronUpdate() makes prior to performing its assertions
  2. why only when I have XDebug on I keep hitting Symfony\Component\Validator\Exception\InvalidOptionsException: The options "requiredKeys" do not exist in constraint "Symfony\Component\Validator\Constraints\Type". in \Drupal\update\ProjectRelease::validateReleaseData() 😳 (I've added an early return for now)
  3. why with XDebug on it's impossible for me to break inside automatic_updates_cron() — it must somehow be crashing earlier, but … I literally can't see it. Yet $this->drupalGet(''); does return a working page. Although I will say that it appears to be hitting the Dynamic Page cache.

P.S.: I already tried logic similar to what \Drupal\Core\Cron::run() does:

  $account_switcher = \Drupal::service('account_switcher');
  assert($account_switcher instanceof \Drupal\Core\Session\AccountSwitcherInterface);
  $fake_root_user = new \Drupal\Core\Session\UserSession(['id' => 1, 'roles' => [\Drupal\Core\Session\AccountInterface::AUTHENTICATED_ROLE]]);
  $account_switcher->switchTo($fake_root_user);

  /** @var \Drupal\automatic_updates\CronUpdateStage $stage */
  $stage = \Drupal::service('automatic_updates.cron_update_stage');
  $stage->handleCron();

  $account_switcher->switchBack();

but no dice either.

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented

re #13.3

why with XDebug on it's impossible for me to break inside automatic_updates_cron() — it must somehow be crashing earlier, but … I literally can't see it. Yet $this->drupalGet(''); does return a working page. Although I will say that it appears to be hitting the Dynamic Page cache.

It this might be because $this->drupalGet('') will be return when the response is returned from the server but only after that does the Kernel Terminate event get fired. So I think if you are debugging it will hit the line after drupalGet while cron is happening in kernel terminate.

I am not sure if this is true in functional tests but I think this is true for build tests.

I am guessing this is why \Drupal\Tests\system\Functional\System\CronRunTest::testAutomatedCron does

$this->drupalGet('');
    sleep(1);

Though this might not work for us since our operation make take longer.

In a branch I was using to debug #3360656: For web cron updates run each stage life cycle phase in a different request where I first found the kernel terminate problem I actually created a <a href="https://git.drupalcode.org/issue/automatic_updates-3360656/-/tree/3360656-split-requests_2debug">visitAndWaitForTerminate</a> function that worked with a test module that would write a file at beginning of the request and delete when the background update operation had finished.

this was crude but I couldn't think of another way to test this and I needed to figure out what was going on

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented

re #14 I pushed a change module that allows test to wait on cron update in kernel terminate

Re #9

We can fix that by adding an optional ?string $owner = NULL to StageBase and UpdateStage, and having CronUpdateStage hardcode that to 'cron' as the owner.

did this actually fix it? That is not what I am seeing. Checked out Allow specifying the owner of the stage to avoid triggering a session in cron/CLI contexts. was actually because \Drupal\automatic_updates\CronUpdateStage::handleCron didn't find a $next_release

wim leers’s picture

wim leers
Location Ghent 🇧🇪🇪🇺
commented

"Fix" in the sense that no new session was triggered anymore.

The problem you're reporting is in line with what I reported at the start of #12 — i.e. that the test itself is wrong.

tedbow’s picture

tedbow
he/him
Primary language English
Location Ithaca, NY, USA
commented
Status: Needs work » Closed (won't fix)

Going to say we won't fix this at least until we first try #3357969: For web server dependent unattended updates run the entire life cycle in a separate process that will not be affected by hosting time limits

that method probably has advantages of using Automated Cron even if we could