Invalid system.schema key_value entry causes fatal on updating to 8.8.5

@dawehner in this patch i have remove extra space in comment.

Running forcefully test on patch #9
https://dispatcher.drupalci.org/job/drupal_patches/45749/

patch in #10 is failed to apply.

Oops, missed this one...

Here's #5 + #6 in a single patch for 8.8.x.

Still fails locally. Here's why:

1. When you get to the 'selection' page on update.php, it calls: update_retrieve_dependencies()
2. That function does a similar loop:
   

       foreach (\Drupal::keyValue('system.schema')->getAll() as $module => $schema) {
   

3. For each thing in 'system.schema', it calls module_load_install()
4. module_load_install() jumps through a few more hoops before it calls drupal_get_filename().
5. drupal_get_filename() does not throw exceptions on errors, but directly calls trigger_error(). :( There's no way to catch that. So the fix in #5 doesn't actually matter. Edit: I was wrong, see below.

I'm not sure how to fix this cleanly without lots of BC breaking.

The yucky / bloaty approach is to not call module_load_include() directly in update_retrieve_dependencies(), but to first use \Drupal::service("extension.list.module") and check that the module exists and is enabled before we try to call module_load_include(). Or something. :(

Sweet, that wasn't nearly as bad as I feared. ;) This now passes locally. It's not even too terrible. Hope the inline comment is sufficient to explain why we need this.

Note: we still also need the fix from #5, so I'm leaving that in. If I take it out, the test starts failing again.

Forward port to 8.9.x and 9.y.x branches.

Oh, forgot to mention at #14. I slightly simplified the test:

-    $this->drupalLogin(
-      $this->drupalCreateUser(
-        [
-          'administer software updates',
-        ]
-      )
-    );
+    $this->drupalLogin($this->updateUser);

This test class already has a protected $updateUser with that permission, so we should re-use that instead of creating another.

Re: #18: Random fail:

There was 1 failure:

1) Drupal\Tests\media_library\FunctionalJavascript\WidgetUploadTest::testWidgetUploadAdvancedUi
"image-1.png" not found
Failed asserting that a boolean is not empty.

Re-queued...

Hi @Dww,

this error is only getting on Drupal CI when automatic running or I check manually then working fine on drupal.org CI also in my local working fine.

I am getting the same error on
https://www.drupal.org/pift-ci-job/1683828
checked manually then working fine.

The patch looks good.

The added test tests the problem as stated in the IS. I would like see a comment about the following line about why this line is here and what is does.

+++ b/core/modules/system/tests/src/Functional/UpdateSystem/UpdateScriptTest.php
@@ -401,6 +401,22 @@ public function testMissingExtension($extension_type) {
+    \Drupal::keyValue('system.schema')->set('my_already_removed_module', 8000);

The fix to update_get_update_list() is necessary, because without it the tests fails with:

Drupal\Tests\system\Functional\UpdateSystem\UpdateScriptTest::testNotExistingModuleInSchema
Exception: Drupal\Core\Extension\Exception\UnknownExtensionException: The module my_already_removed_module does not exist.
Drupal\Core\Extension\ExtensionList->get()() (Line: 265)

The fix to update_retrieve_dependencies() is necessary, because without it the tests fails with:

Drupal\Tests\system\Functional\UpdateSystem\UpdateScriptTest::testNotExistingModuleInSchema
Exception: User warning: The following module is missing from the file system: my_already_removed_module
drupal_get_filename()() (Line: 181)

I like the added log the error stuff. In this way we will get a better understanding about where these bugs come from. :)
With the added comment, the patch will be for me RTBC.

I've added a brief note about this to #3130037: system.schema information gets out of sync with module list (which was already open to track modules having missing system.schema information), and retitled it so that it covers either direction of going out of sync.

Opened #3137197: Delete orphaned system.schema entries. to discuss automatically cleaning up the system.schema cruft (for Drupal 10).

Do we want to add a \Drupal::messenger() warning in this issue, so that we have an additional chance to alert site owners that something is up? It could result in more reports of this which may help to track down the root cause.

Another possible issue (or two):

1. If the module is in the code base, has the orphaned system.schema entry, but is not installed, will we then be locating and trying to run updates for it? i.e. have we accidentally re-introduced running updates on uninstalled modules when this happens?

2. If the module is not in the code base, but then is re-added, what happens if you try to install it again? Do we just ignore the system.schema entry and overwrite it, or does it cause problems?

I don't think #2 is as critical as this issue - since it would only prevent you re-installing that specific module as opposed to being able to run updates (i.e. we should split it out to a follow-up if it is), but #1 would be and could probably be handled here.

@shaktik Re: #20: I'm not understanding your comment. The tests are all working as expected, both on the drupal.org testbot and when running them locally. If you're seeing skipped tests locally, something is wrong with your testing environment. Helping you debug your setup is out of scope for me and my time today, sorry.

@daffie: Re: #21: Thanks for the review. Re: \Drupal::keyValue('system.schema')->set('my_already_removed_module', 8000);, I was hoping that the name of the test (testNotExistingModuleInSchema()) and the existing summary ("Tests that orphan schemas don't prevent updates.") was sufficient. But I'm always up for more comments, so here you go. ;)

@catch: Re: #22: Thanks for the review, follow-up and the questions.
Re: dsm(): Sure, I guess that's fine. For now, duplicated exactly the message that gets logged. However, I'm worried that the message is sort of scary sounding but totally non-actionable for 99% of site admins. :(

Module %name has a schema in the key_value store, but is not installed.

<hat class="average-site-builder">

• So what?
• Now what?
• How do I fix this warning?
• Drupal Is Broken(tm)!

</hat>

Not even drush gives you an easy way to clean up the k/v store. AFAIK, you have to do direct DB manipulations or PHP eval to try to clean this out.

Do we really want to present this to site admins like this? If so, I think we need a better message that either explains what to do, or at least links to a handbook page on d.o that does.

Re: #22.1: I can't fathom how adding code to update.inc that gives it more reasons to skip trying to run updates for something would re-introduce the bug you're talking about. 😉 Also, don't we already have existing test coverage of that original bug? If not, what happened?!? 😜 If so, why can't we trust it to make sure this hasn't re-broken it? I briefly skimmed through the rest of UpdateScriptTest.php and didn't see anything, but I'm not totally fluent in all the update.php tests and what they cover. Seems out of scope here to add such coverage if it doesn't already exist, especially since it seems impossible that this change would re-trigger that bug. This patch only makes it more likely that we don't try to run updates we shouldn't run.

Re: #22.2: That seems to work just fine:

# Clean slate, nothing installed, nothing in system.schema.
# Insert the bogus value:
% drush ev "\Drupal::keyValue('system.schema')->set('custom', 7000);"
# Verify it.
% drush ev "echo \Drupal::keyValue('system.schema')->get('custom')"
7000
% drush en custom
 [success] Successfully enabled: custom
% drush ev "echo \Drupal::keyValue('system.schema')->get('custom')"
8000

So probably NW for a better message to show admins and stuff in the logs. Perhaps we need a handbook page first so we can link to it. TBD. /shrug

p.s. at #3110198-53: [META] Beta targets following Drupal 9.0.0-beta1 and 8.9.0-beta1 @catch wrote:

That will affect sites updating to 8.7.13 too, although only if they already have corrupted system.schema information in that specific way.

Not worth bot cycles for this (yet), but FYI, the 8_8_x patch applies cleanly to 8.7.x branch and the new test passes there, too.

Added a \Drupal::messenger() warning to the patch as requested by @catch.
Added a comment to the test as requested by myself.
The warning message text could/should be improved, only nobody has any idea.
As this issue is blocking the release of 9.0-rc1, I am not going to block it on a better warning message text.
All code changes look good to me.
For me it is RTBC.

I can't fathom how adding code to update.inc that gives it more reasons to skip trying to run updates for something would re-introduce the bug you're talking about.

I don't mean that this issue will re-introduce a bug, I'm asking whether we have a separate bug related to orphaned system.schema entries that is not covered here, potentially introduced by #2917600: update_fix_compatibility() puts sites into unrecoverable state.

The current patch and test coverage covers:

A module, that was previously installed, that has orphaned data in system.schema, that is no longer in the file system.

It does not cover:

A module, that was previously installed, that has orphaned data in system.schema, that is still in the file system.

In that case, there will probably not be an exception thrown from ::checkIncompatibility(), and system.schema is returning 8000 or whatever instead of SCHEMA_UNINSTALLED - so, what happens? Do we hit an error later? Do the updates get added to the list? Does it get filtered out again somewhere when we switch back to extension.list instead of system.schema in a foreach so that things are eventually fine? Even if there's not a functional bug in the end, we should add test coverage for that.

@catch: Thanks for clarifying! Now I understand you. Indeed, that's broken. :( Sounds like we need to fix that here?

This fixes the new test. Not sure if this is cool, or will break something else. Let's see if the bot spots any other troubles.

Okay, so that's encouraging. The bot is happy with all the other update tests with the fix in #29. Yay.

Here's the interdiff between patches 23 and 28, which might be more clear than the intervening interdiffs since there's nothing about drupalci.yml in this.

Updating summary a bit now that this is getting closer to done.

One thought on the fix from #29: do we want to detect that case explicitly and add another dsm/log message about it? Honestly, the existing message is more accurate for the present-but-not-installed case:

Module %name has a schema in the key_value store, but is not installed.

Perhaps we should change the message in the not-present case to something like:

Module %name has a schema in the key_value store, but is missing from your site.

If we're changing the messages, perhaps we can make them more clear / actionable, too (see #23).

Thoughts?

Thanks,
-Derek

This handles the possible error conditions separately so we can have more specific warning messages:

More specific tests. Not sure this is an improvement over #31, but instead of checking the whole page, make sure the status text is in a status message, and that the warning text is in a warning message. /shrug Stark doesn't use classes, so instead of searching for div.messages-status, we need to xpath() for @aria-label="Status message"...

Adds coverage that there aren't unexpected warnings.

Also adds coverage for the situation where both warnings are displayed.

Finally, I'm removing a stay visit to the status report that's from the original test in #6:

+++ b/core/modules/system/tests/src/Functional/UpdateSystem/UpdateScriptTest.php
@@ -400,6 +400,28 @@ public function testMissingExtension($extension_type) {
+    $this->drupalGet($this->statusReportUrl);

Seems we don't need that as part of this test...

Sorry, patches in #32 were a bit wonky. Didn't correctly apply the changes to all the branches. Try these, instead.

In case it's helpful, interdiff between #31 and #33...

A module, that was previously installed, that has orphaned data in system.schema, that is still in the file system.

This is what @catch wants to add to the patch. The added check: if (!$module_handler->moduleExists($module)) { does exactly that. There is also automatic testing added in the patch for that.
All points of @catch are addressed.
All code changes look good.
Back to RTBC.

This is looking a lot better, comments are not major but the second one means back to Needs Review.

1. +++ b/core/includes/update.inc
   @@ -340,11 +341,32 @@ function update_get_update_list() {
   +      }
   +    }
   +    // It is possible that the system schema has orphaned entries, so the
   +    // incompatibility checking might throw an exception.
   +    catch (UnknownExtensionException $e) {
   +      $args = ['%name' => $module];
   +      \Drupal::messenger()->addWarning(t('Module %name has a schema in the key_value store, but is missing from your site.', $args));
   +      \Drupal::logger('system')->notice('Module %name has a schema in the key_value store, but is missing from your site.', $args);
          continue;
        }
   +    // There might be orphaned entries for modules that are in the filesystem
   +    // but not installed. Also skip those, but warn site admins about it.
   +    if (!$module_handler->moduleExists($module)) {
   +      $args = ['%name' => $module];
   +      \Drupal::messenger()->addWarning(t('Module %name has a schema in the key_value store, but is not installed.', $args));
   +      \Drupal::logger('system')->notice('Module %name has a schema in the key_value store, but is not installed.', $args);
   +      continue;
   +    }
   +
   

   +1 on the changed messages. Also makes it much clearer exactly what the different error conditions are by moving (compared to earlier patches) the ::moduleExists() check under a dedicated comment.

2. +++ b/core/includes/update.inc
   @@ -631,10 +653,15 @@ function update_already_performed($module, $number) {
      // the same order that \Drupal::moduleHandler()->invokeAll() does.
      foreach (\Drupal::keyValue('system.schema')->getAll() as $module => $schema) {
   -    if ($schema == SCHEMA_UNINSTALLED) {
   +    // Skip modules that are entirely missing from the filesystem here, since
   +    // module_load_install() will call trigger_error() if invoked on a module
   +    // that doesn't exist. There's no way to catch() that, so avoid it entirely.
   +    if ($schema == SCHEMA_UNINSTALLED || !$extension_list->exists($module)) {
          // Nothing to upgrade.
          continue;
        }
   

   This doesn't have the ::moduleExists() check, does that matter? Also the comment doesn't mention orphaned system.schema entries. Is the hunk even needed with the rest of the patch?

3. +++ b/core/modules/system/tests/src/Functional/UpdateSystem/UpdateScriptTest.php
   @@ -401,6 +401,68 @@ public function testMissingExtension($extension_type) {
   +
   +    // First, insert a bogus value into the system.schema key/value storage for
   +    // a non-existant module. This replicates what would happen if you had a
   +    // module installed and then completely remove it from the filesystem
   

   Nit: shouldn't this be existent? Or is that British vs. American?

   I think there's an extra step involved to reach this condition 1. You had the module installed but removed it from the filesystem without uninstalling 2. You 'manually' uninstalled in extension.list without removing the system.schema entry. If the module is in extension.list but not the filesystem, that's a different problem for which we already have error messages.

   Also maybe this is actually how people are getting into this position? If so we might not actually have a core bug causing this as such.

+++ b/core/includes/update.inc
@@ -340,11 +341,32 @@ function update_get_update_list() {
+  /** @var \Drupal\Core\Extension\ModuleHandler $module_handler */
+  $module_handler = \Drupal::moduleHandler();
...
+    // There might be orphaned entries for modules that are in the filesystem
+    // but not installed. Also skip those, but warn site admins about it.
+    if (!$module_handler->moduleExists($module)) {

I don;t think we need a new dependency here. The extension list know which modules are installed. See \Drupal\Core\Extension\ExtensionList::getInstalledExtensionNames()

Hi @alexpott this the protected method i think we can not use directly in .inc file.This function can we use by using the class.
One more think this function has implemented on "extension.list.module" service in protected manner which internally use "$this->moduleHandler->getModuleList()" .
So i think it was not an issue
Please correct me if am wrong.

@pavnish good point. We can get a list using \Drupal\Core\Extension\ExtensionList::getAllInstalledInfo() and then check if the module is not in this list.

One concern is what is the correct action to take at this point. We can:

• Report the error and soldier on like we're doing here
• Halt the update - your code and database state is inconsistent. This has problems because you might need a security update and this would prevent you until you've manually fixed the table.
• Report the error and clean up the state. This has problems too because maybe there's other stuff left lying around from the module.

All pretty awkward but what we're currently doing is probably best.

We have #3137197: Delete orphaned system.schema entries. for deleting entries, I'm suggesting doing that in Drupal 10 in an update.

The big question with this is whether things getting out of sync is due to force-uninstalls by admins - in which case it's good to handle and warn about it, but ultimately self-inflicted, or due to core and contrib bugs - like a fatal error during uninstall. And also whether we can ever prevent either of those from happening permanently.

Discussed this in the #d9readiness meeting today. I'll work on the following:

1. We need a CR for this.
2. @xjm, @catch and I agreed that the warning messages should link to the CR for more info. "<a href=":link">More information about this error.</a> tacked on the end."
3. #36.2: I'll add more comments. But yes that hunk matters, and no it doesn't need moduleExists() there. If you remove that hunk, the test fails like so:
   

   There was 1 error:
   
   1) Drupal\Tests\system\Functional\Update\UpdateScriptTest::testOrphanedSchemaEntries
   Exception: User warning: The following module is missing from the file system: my_already_removed_module
   drupal_get_filename()() (Line: 295)
   

   As it says, we can't call module_load_install() on something not in the filesystem or we get an uncatchable trigger_error(), not an exception. This is actually in update_retrieve_dependencies(). We don't need to filter out not-installed here, because that happens in update_get_update_list(). We could also filter those out here, and the tests still pass, but that seems like maybe scope creep? I defer to core committers on their preference for this.

4. #36.3: Indeed, typo. s/non-existant/nonexistent/ (a vs. e, plus we don't need the hyphen).
5. #40.

Very preliminary CR here: https://www.drupal.org/node/3137656 -- If anyone wants to edit that to be real, please do. ;)

This fixes everything else I mentioned in #44. This is only the 8.8.x branch patch. I'll forward port after breakfast, assuming folks are happy with all this.

Forward ports.

Initial real version of the CR: https://www.drupal.org/node/3137656/revisions/view/11880555/11880653
Also, refreshing the screenshots, now that we have a link in the warning messages.

I reworded the warnings to be a bit more useful for mere mortals:

Module %name has a schema in the key_value store, but is missing from your site.
Module %name has a schema in the key_value store, but is not installed.

• If people are going to be fixing this, they need to know the actual k/v table name ("system.schema").
• What's a "key_value store"? Is that where I buy valuable keys? Huh?

Now:

Module %name has an entry in the system.schema key/value storage, but is missing from your site.

Module %name has an entry in the system.schema key/value storage, but is not installed.

p.s. "Maybe "key/value service..." would be better than "storage"?

The CR is to me good enough. It has a good describtion about the newly added warning message. Including what a siteowner can do to cleanup the error.
All shown warnings are also logged and all have a link to the CR.
There are 2 different warnings that are shown, depending on whether the source module is on the file system or not. For both and for the combination is automatic testing added.
All code changes look good to me and all are very commented.
We have a followup for cleaning up the orphaned system.schema entries. See: #3137197: Delete orphaned system.schema entries..
For it is all good enough. We need to ship Drupal 9.0 and not spending a lot of time trying to get this issue perfect. Even so, I must say that the effort of @dww is very much appreciated!
For me it is RTBC.

Thanks for the CR and the additional comments/message improvements, all looks good to me now.

Committed/pushed to 9.1.x, cherry-picked to 9.0.x, and then the 8.9.x and 8.8.x patches, thanks!

@catch Thanks! Looks like you didn't push the 8.8.x commit...

Hmm, now pushed!

Wonderful, thanks.