Problem/Motivation
We had an issue present on a website where after deployments tokens would suddenly stop working. I originally thought this was an issue in the token contrib module as the problem presented itself in the same way as
https://www.drupal.org/project/token/issues/3088219#comment-13972171
🐛
Inconsistent loading of third party hook implementations
Fixed
When in a bad state, we could observe that in the module_implements cache had an empty array for the module_implements_alter key of the bootstrap cache.
drush ev "print_r(\Drupal::service('module_handler')->getImplementations('module_implements_alter'))"
Array
(
)
After a lot of debugging I suspect what is happening is a race condition triggered by a module the calls $moduleHandler->alter() in its logger constructor, which is a dependency of some StackMiddleWare.
This resulted in the logger being constructed when the kernel is constructed - which is before DrupalKernel is loading the module files.
On the first request the cache for key hook_info will be empty so the module handler calls buildHookInfo() and saves that to the cache. buildHookInfo has a safety check to reload the module files https://git.drupalcode.org/project/drupal/-/blob/10.1.x/core/lib/Drupal/...
When buildImplementationInfo('module_implements_alter') is called the ModuleHandler has already loaded the module files and so it returns the expected list. This is statically cached and then saved to the cache at the end of the request.
What I think is happening is that a second request starts and is able to load key hook_info from the cache, however if the first request has not completed the cache for key module_implements_alter is still empty - so it will produce an empty result for module_implements_alter.
The first request then writes to the cache, and then the second request completes and writes to the cache again, this time with an empty array for module_implements_alter.
Steps to reproduce
This relies on a combination of things outside of core.
I was able to reproduce it through
- enabling the cloudflare contributed module (which has middleware that has a dependency on a logging channel)
- enabled the raven contributed module (which has a logger channel that calls ModuleHandler->alter in its constructor - but note that raven module now works around this issue by only invoking the alter hook if configured to do so)
# Clear the cache
drush cr
# Ensure Drupal has cached hook info
drush ev "\Drupal::service('module_handler')->getHookInfo()"
# Manually drop the module_implements cache to mimic a scenario where the original request started but not complete
drush ev "\Drupal::service('cache.bootstrap')->delete('module_implements')"
After loading the website in the browser I can see that module_implements alter is empty.
Proposed resolution
Should the module handler include a similar safety check to buildHookInfo in buildImplementationInfo to verify that the modules are loaded?
Is this a documentation issue -
https://www.drupal.org/docs/drupal-apis/middleware-api →
does not set expectations around what services and functionality should be available to middleware.
Remaining tasks
- Decide if this is an issue for Core or not
User interface changes
n/a
API changes
-
Data model changes
n/a
Release notes snippet
-