Problem/Motivation

Coming from / related issue: #3207813: ModuleHandler skips all hook implementations when invoked before the module files have been loaded

During deployment, in the config:import phase, when there are modules to be uninstalled and installed at the same time, invoking hooks can lead to a fatal error if the file containing them have not been loaded yet.

This seems to be a regression from #3505049: Drupal 11.1.2 upgrade causes \Drupal::$container is not initialized yet error introduced in 11.2.3.

Steps to reproduce

On clean 11.x with demo_umami and devel
Steps:
- composer require --dev drupal/devel drush/drush
- drush si demo_umami -y
- drush cex -y
- Now go to sites/default/files/sync/core.extension.yml:40 and replace page_cache: 0 with devel: 0
- drush cim -y

 // Import the listed configuration changes?: yes.                                                                      

>  [notice] Synchronized extensions: uninstalled page_cache.
>  [error]  Error: Call to undefined function \devel_entity_type_alter() in Drupal\Core\Extension\ModuleHandler->alter() (line 479 of /var/www/html/core/lib/Drupal/Core/Extension/ModuleHandler.php) #0 /var/www/html/core/lib/Drupal/Core/Plugin/DefaultPluginManager.php(389): Drupal\Core\Extension\ModuleHandler->alter()
...stracktrace...

Stacktrace: https://gist.github.com/vever001/a80414b43d317d84e1d1aacc91cbb895

Proposed resolution

Make hook invocation resilient by ignoring registered hooks that aren’t actually callable at runtime.
See comments #16, #17, #20

Remaining tasks

None?

User interface changes

N/A

Introduced terminology

N/A

API changes

N/A

Data model changes

N/A

Release notes snippet

N/A

CommentFileSizeAuthor
#38 3549397-38.diff3.06 KBherved
#21 3549397-nr-bot_6wl05if2.txt1.53 KBneeds-review-queue-bot
#19 3549397-nr-bot_u77pmzpz.txt91 bytesneeds-review-queue-bot

Issue fork drupal-3549397

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

herved created an issue. See original summary.

herved’s picture

herved commented

Observations (so far):
- In that example, it seems to involve \Drupal\language\EventSubscriber\LanguageRequestSubscriber::onContainerInitializeSubrequestFinished, which gets called when devel gets installed. The container gets -reinitialized and triggers all the language negociation handlers and eventually hook_entity_type_alter.

This doesn't seem to be a problem when the deployment only contains a module install.
However when a module gets uninstalled (i.e.: page_cache), then ModuleInstaller::uninstall clears cached (entity) definitions at the end (see "// Flush all persistent caches.")

- Applying the patch from #3207813-95: ModuleHandler skips all hook implementations when invoked before the module files have been loaded solves it, but does it really make sense that devel_entity_type_alter gets called while devel is not actually installed yet?
- Another possible fix might be to ensure the hook is actually callable before adding to the list in \Drupal\Core\Extension\ModuleHandler::getFlatHookListeners

--- a/core/lib/Drupal/Core/Extension/ModuleHandler.php
+++ b/core/lib/Drupal/Core/Extension/ModuleHandler.php
@@ -752,7 +752,7 @@ protected function getFlatHookListeners(string $hook): array {
           else {
             $callable = $listener;
           }
-          if (isset($this->moduleList[$module])) {
+          if (isset($this->moduleList[$module]) && is_callable($callable)) {
             $this->listenersByHook[$hook][] = $callable;
             $this->modulesByHook[$hook][] = $module;
           }

Would that be a better solution?

herved’s picture

herved commented
Issue summary: View changes
berdir’s picture

berdir
Primary language German
Location Switzerland
commented

An is callable is an option to avoid fatal errors, silently ignoring things is always a bit tricky if something unexpected happens, e.g. discovery of a callback that can't be loaded.

I think what should solve this problem in this case is moving the load() calls to the moduleHandler above updateKernel() in \Drupal\Core\Extension\ModuleInstaller::doInstall. I think that's consistent with how we register class namespaces as well, which also happens before the container is rebuilt.

herved’s picture

herved commented

#4, indeed that also seems to work.
OTOH it seems a bit strange to me that devel_entity_type_alter gets called while devel is not installed yet. Is that a concern?
At this stage, it is still in the preparation phase calling $this->updateKernel in ModuleInstaller::doInstall.

I'm not sure what is the safest option to apply until a proper fix is found. I may go with the is_callable option for now...

herved opened merge request !13355

herved opened merge request !13357

berdir’s picture

berdir
Primary language German
Location Switzerland
commented

> OTOH it seems a bit strange to me that devel_entity_type_alter gets called while devel is not installed yet. Is that a concern?

As far as HookCollectorPass is concerned, devel *is* installed at that point, because it exists in the modules list in the kernel. I agree it could be a problem if a hook is invoked that relied on something from the module, but invoking hooks while rebuilding the kernel is an extremely bad idea anyway. It's going through multiple layers, it's also relevant that you have admin language negotiation enabled (\Drupal\user\Plugin\LanguageNegotiation\LanguageNegotiationUserAdmin), which is the thing that's doing a permission check, which in turn is what is causing the role config entities to be loaded, which is invoking those hooks.

herved’s picture

herved commented

it's also relevant that you have admin language negotiation enabled

Exactly, this is why I used demo_umami to reproduce the issue I have on my project.

I identified https://git.drupalcode.org/project/drupal/-/commit/78813e01c72ff50265df2... as the first failing commit which was introduced in 11.2.3. Issue: #3505049: Drupal 11.1.2 upgrade causes \Drupal::$container is not initialized yet error
Specifically, lines 406-411 removed in core/lib/Drupal/Core/Hook/HookCollectorPass.php
So this could be seen as regression.

herved’s picture

herved commented
Title: Uninstalling and installing modules during config:import can lead to fatal errors » [Since 11.2.3] Uninstalling and installing modules during config:import can lead to fatal errors
Issue summary: View changes
herved’s picture

herved commented

So far 4 options/ideas:

1. Adding is_callable causes 1 test fail and seems to go against: ModuleHandlerTest::testImplementsHookModuleEnabled

2. Loading module files before updateKernel causes 1 test to fail: ClassLoaderTest::testAutoloadFromModuleFile
Here is the stacktrace:

Error: Class "Drupal\module_autoload_test\SomeClass" not found in include_once() (line 12 of core/modules/system/tests/modules/module_autoload_test/module_autoload_test.module).
Drupal\Core\Extension\Extension->load() (Line: 143)
Drupal\Core\Extension\ModuleHandler->load() (Line: 323)
Drupal\Core\Extension\ModuleInstaller->doInstall() (Line: 229)
Drupal\Core\Extension\ModuleInstaller->install() (Line: 83)
Drupal\Core\ProxyClass\Extension\ModuleInstaller->install() (Line: 503)
Drupal\system\Form\ModulesListForm->submitForm()
call_user_func_array() (Line: 105)
Drupal\Core\Form\FormSubmitter->executeSubmitHandlers() (Line: 43)
Drupal\Core\Form\FormSubmitter->doSubmitForm() (Line: 616)
Drupal\Core\Form\FormBuilder->processForm() (Line: 348)
Drupal\Core\Form\FormBuilder->buildForm() (Line: 73)
Drupal\Core\Controller\FormController->getContentResult()
call_user_func_array() (Line: 123)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 633)
Drupal\Core\Render\Renderer::Drupal\Core\Render\{closure}()
Fiber->start() (Line: 634)
Drupal\Core\Render\Renderer->executeInRenderContext() (Line: 121)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext() (Line: 97)
Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}() (Line: 183)
Symfony\Component\HttpKernel\HttpKernel->handleRaw() (Line: 76)
Symfony\Component\HttpKernel\HttpKernel->handle() (Line: 36)
Drupal\Core\Test\StackMiddleware\TestWaitTerminateMiddleware->handle() (Line: 53)
Drupal\Core\StackMiddleware\Session->handle() (Line: 48)
Drupal\Core\StackMiddleware\KernelPreHandle->handle() (Line: 28)
Drupal\Core\StackMiddleware\ContentLength->handle() (Line: 118)
Drupal\page_cache\StackMiddleware\PageCache->pass() (Line: 92)
Drupal\page_cache\StackMiddleware\PageCache->handle() (Line: 48)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle() (Line: 51)
Drupal\Core\StackMiddleware\NegotiationMiddleware->handle() (Line: 53)
Drupal\Core\StackMiddleware\AjaxPageState->handle() (Line: 54)
Drupal\Core\StackMiddleware\StackedHttpKernel->handle() (Line: 716)
Drupal\Core\DrupalKernel->handle() (Line: 19)

3. Use loadAll hack from #3207813-95: ModuleHandler skips all hook implementations when invoked before the module files have been loaded
Also fails on ModuleHandlerTest::testImplementsHookModuleEnabled

4. Should the fix focus on the language module and LanguageRequestSubscriber::onContainerInitializeSubrequestFinished which is what is causing havoc here during container rebuild ?
That code originates from #2650434: Clearing cache via UI in translated language resets config translation of field labels to default language, interestingly I cannot reproduce that issue after commenting that event listener, and the corresponding test from ConfigTranslationCacheTest.php passes without it...

nicxvan’s picture

nicxvan commented

Great detective work.

1. I think we should not do this, it's just covering the symptom.

2. I think we should explore this.

3. I think we should avoid this, I don't have a concrete reason, but it feels like a bandaid more than a fix.

4. We should probably explore this as well.

herved opened merge request !13372

herved’s picture

herved commented

I could use some help, but this language subscriber is very suspicious...
For now one workaround is to uninstall modules with a post_update hook instead of letting config:import do it.

nicxvan’s picture

nicxvan commented
Related issues: +#3531920: hook_install() may not work as intended, if modules installed in bulk
berdir’s picture

berdir
Primary language German
Location Switzerland
commented

FWIW, I've suggested that we do an is_callable() at runtime in #3495051: ModuleHandler::invokeAllWith() does not check listener is actually callable at the moment a while ago (forgot about that issue, it's partially a duplicate of this), we had that in the old hook system as well.

The specific issue here is limited to legacy hooks in a .module file, it would not happen with OOP hooks because those hooks too are then part of the container and should be load-able. That said, I still think a runtime check doesn't hurt, if only to make it easier to recover a possibly broken site when code has been removed (a module or even just a single method). That scenario will also apply to OOP hooks.

It also slightly overlaps with #3506930: Separate hooks from events because that will change it from a fatal error when trying to invoke that callback to an exception thrown by CallableResolver when trying to resolve that callback. If nothing else, it means thata we'll need a different MR/change if/when we backport this to 11.2

berdir’s picture

berdir
Primary language German
Location Switzerland
commented
Status: Active » Needs review

I had a look at the is callable approach test fail. I think that's just an incomplete setup in the unit test, as unit tests typically just set up what they actually need. If you extend that method with an invokeAll() then it fails with a fatal error, because module_handler_test_added_hook is in a hook.inc file that isn't being loaded.

It's even weirder considering that it talks about runtime added module, but there's no runtime adding here, because that has been deprecated and removed in #3481778: Deprecate functions using ModuleHandler::add().

So IMHO, the line with module_handler_test_added is pretty bogus and we can just remove that. We could improve the mocking in that test and add the necessary include file to ProceduralCall, but we're really just adding more legacy stuff and would conflict more with #3506930: Separate hooks from events. It also uses legacy hooks, but it's not a legacy/deprecation test, because legacy hooks don't trigger deprecations yet and we'll need to convert it into OOP hooks anyway.

berdir opened merge request !13461

needs-review-queue-bot’s picture

needs-review-queue-bot commented
Status: Needs review » Needs work
StatusFileSize
new 3549397-nr-bot_u77pmzpz.txt91 bytes

The Needs Review Queue Bot tested this issue. It no longer applies to Drupal core. Therefore, this issue status is now "Needs work".

This does not mean that the patch necessarily needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide to find step-by-step guides for working with issues.

berdir’s picture

berdir
Primary language German
Location Switzerland
commented
Status: Needs work » Needs review

There are now two callable merge requests, one against 11.2 for backport, and a rebased but almost completely changed one against 11.x Things are quite different there. The previously failing test no longer fails, because I fixed the include bits already in the separate hooks issue. Also added an explicit test with an invalid definition.

needs-review-queue-bot’s picture

needs-review-queue-bot commented
Status: Needs review » Needs work
StatusFileSize
new 3549397-nr-bot_6wl05if2.txt1.53 KB

The Needs Review Queue Bot tested this issue. It fails the Drupal core commit checks. Therefore, this issue status is now "Needs work".

This does not mean that the patch necessarily needs to be re-rolled or the MR rebased. Read the Issue Summary, the issue tags and the latest discussion here to determine what needs to be done.

Consult the Drupal Contributor Guide to find step-by-step guides for working with issues.

berdir’s picture

berdir
Primary language German
Location Switzerland
commented
Status: Needs work » Needs review
Issue tags: +no-needs-review-bot

bot is confused about the 11.2 MR.

nicxvan’s picture

nicxvan commented

Can we clean this issue up a bit? Close the one that isn't relevant anymore and move the language fix to a separate issue?

Also can we update the IS?

smustgrave’s picture

smustgrave commented
Status: Needs review » Needs work

Will agree with #23

herved changed the visibility of the branch 3549397-move-load to hidden.

herved changed the visibility of the branch 3549397-delete-language-subscriber to hidden.

herved’s picture

herved commented

Created #3558942: Investigate whether LanguageRequestSubscriber::onContainerInitializeSubrequestFinished() is still required and appropriate

herved’s picture

herved commented
Issue summary: View changes
Status: Needs work » Needs review

Thank you @berdir!
I rebased both branches, it seems tests are passing.
Tried summarizing the solution in the IS, but feel free to adjust if needed, thanks.

smustgrave’s picture

smustgrave commented

Assuming the 11.2 branch will have to be 11.3 now?

berdir’s picture

berdir
Primary language German
Location Switzerland
commented

No, it just means that it won't be backported anymore to that and that MR is no longer relevant.

nicxvan closed merge request !13461

john.oltman’s picture

john.oltman commented

The new MR for 11.3 worked for me, thank you @herved

Version: 11.x-dev » main

Drupal core is now using the main branch as the primary development branch. New developments and disruptive changes should now be targeted to the main branch.

Read more in the announcement.

smustgrave’s picture

smustgrave commented
Status: Needs review » Needs work

Sorry this is one where the auto change to main may have hurt? Could 13355 be rebased. Can I assume the other hidden MRs can be closed?

herved closed merge request !13357

herved closed merge request !13372

herved’s picture

herved commented
Status: Needs work » Needs review

yes, MR rebased, closed the others.

herved’s picture

herved commented
StatusFileSize
new 3549397-38.diff3.06 KB

MR rebased, attaching snapshot for composer.

smustgrave’s picture

smustgrave commented

Should we log something during the exception?

oily’s picture

oily commented

The Test-only test shows failing test code:

https://git.drupalcode.org/issue/drupal-3549397/-/jobs/9255778

oily’s picture

oily commented

Re: #39 I am not sure anything needs to be logged? Not sure an error status message would be appropriate? So something more informational? Not sure there is anything to report?

smustgrave’s picture

smustgrave commented
Status: Needs review » Reviewed & tested by the community

Since there's been no follow up going to mark and see what committers think.

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented
Status: Reviewed & tested by the community » Needs work

This fix does not feel correct. The order of uninstalls and installs means that this should not occur - see \Drupal\Core\Config\ConfigImporter::getNextExtensionOperation() - we process uninstalls and then installs - devel_entity_type_alter should not be called without devel being installed correctly.

berdir’s picture

berdir
Primary language German
Location Switzerland
commented

> devel_entity_type_alter should not be called without devel being installed correctly.

It's not about config import at all I think. It's ultimately about the disconnect between when we consider a module installed. HookCollectorPass looks at the list of modules in the kernel/container. When installing a module, this contains the new module when rebulding the container. However, we have not yet loaded the .module file for it. The collector still finds that, registers it and if then someone triggers the hook during the container build, which unfortunately happens for language stuff atm, it won't find it.

This is restricted to the BC layer, but the idea here is also to protect against code being removed, I think you can currently produce the same exception when you develop and remove a defined hook method, or rename or so. I'm unsure how much we want to handle that honestly. But we did protect against completely removing modules to a certain degree in the past and give you warnings on updating instead of hard errors.

alexpott’s picture

alexpott
he/they
Primary language English
Location 🇪🇺🌍
commented

What I don't understand at the moment is why we need to uninstall the page_cache module in the config import to trigger the error.

Like why if you install umami and then enable the devel module doesn't this always occur? I've tried to debug this but it's a lot of code step through and highly complex. I suspect this is happening because caches are protecting us when we're only doing the install but if you do the uninstall as part of the config import these caches are cleared and no longer protect us on install.

I'm concerned that the fix here will make it harder to debug some errors because we're just eating them.

quietone’s picture

quietone commented
Title: [Since 11.2.3] Uninstalling and installing modules during config:import can lead to fatal errors » [regression] Uninstalling and installing modules during config:import can lead to fatal errors

Changing title per Special titles.

herved’s picture

herved commented

why if you install umami and then enable the devel module doesn't this always occur?

See #2

This doesn't seem to be a problem when the deployment only contains a module install.
However when a module gets uninstalled (i.e.: page_cache), then ModuleInstaller::uninstall clears cached (entity) definitions at the end (see "// Flush all persistent caches.")

I suspect this is happening because caches are protecting us when we're only doing the install but if you do the uninstall as part of the config import these caches are cleared and no longer protect us on install. I'm concerned that the fix here will make it harder to debug some errors because we're just eating them.

Yes, I think LanguageRequestSubscriber::onContainerInitializeSubrequestFinished is really what causes havoc in the first place, because it causes hooks to fire very early at a time when the container is still unstable - #3558942: Investigate whether LanguageRequestSubscriber::onContainerInitializeSubrequestFinished() is still required and appropriate.
Then the fix here adds an extra protection.