| Project: | Drupal core |
| Version: | 7.x-dev |
| Component: | update system |
| Category: | bug report |
| Priority: | critical |
| Assigned: | dww |
| Status: | closed (fixed) |
| Issue tags: | Drupal update |
Issue Summary
I searched for an existing issue about this and didn't find one, apologies in advance if this is duplicate...
While working on #606190: Fix handling of database schema updates in update manager workflow I found a critical bug in drupal_get_schema_versions() which is called from system_requirements() and update.php. Steps to reproduce:
- Install a clean D7 HEAD test site with no contribs, enable the Update manager
- Install update_test_module 7.x-1.0 into sites/all/modules/update_test_module
- Enable the "DUMMY Update test module" at admin/modules -- you'll see the version is 7.x-1.0, etc.
SELECT schema_version FROM system WHERE name = 'update_test_module'=> 1000- Install update_test_module 7.x-1.3 into sites/defaults/modules
- Visit admin/modules and save the page -- you'll see that the version for "DUMMY Update test module" is now 7.x-1.3
- Look at sites/default/modules/update_test_module/update_test_module.install and notice that update_test_module_update_1001() exists
SELECT schema_version FROM system WHERE name = 'update_test_module'still gives 1000 as expected- Visit update.php and watch it tell you there are no pending updates :(
- Visit admin/reports/status and watch it tell you:
DATABASE UPDATES | Up to date
:(
I don't really have time to track this down right now, since I'm desperately trying to fix UI bugs in update manager before the string freeze *really* hits when 7.0-alpha1 ships... But, there's something going wrong with where $functions = get_defined_functions(); is pulling in functions, since it's definitely reading sites/all/modules/update_test_module/update_test_module.install, even though the .info file and .module file we're using are in sites/default/modules/update_test_module/*. :(
Comments
#1
I can confirm this as well. dww points out that clearing cache (specifically system_list) "solves" the problem.
#2
A little more debugging reveals something interesting here... if you clear your cache, namely {cache_bootstrap} cid = system_list, it all works properly. Why? Because system_list['filepaths'] is cached wrong. And, there's the following fun in system_list():
<?php// To avoid a separate database lookup for the filepath, prime the
// drupal_get_filename() static cache with all enabled modules and themes.
foreach ($lists['filepaths'] as $item) {
drupal_get_filename($item['type'], $item['name'], $item['filepath']);
}
?>
I'm not 100% sure yet why this partly works, and the modules page finds the right copy and loads that, whereas the .install parsing code does not. :(
In IRC, pwolanin pointed me to #651086: Cache clearing is an ineffective mess in module_enable() and system_modules_submit() -- it's possible this is somehow related.
#3
I'm not 100% sure yet why this partly works, and the modules page finds the right copy and loads that, whereas the .install parsing code does not. :(
Because it doesn't. ;) The modules page is actually lying. Until you clear {cache_bootstrap}, it's actually still loading the code from sites/all/modules/update_test_module. If you put a PHP syntax error in the copy in sites/default/modules/update_test_module, your site hums along just fine. Once you clear the cache, the site starts blowing up with the syntax error.
#4
Based on #3, the old title wasn't accurate. Really, the bug here is that if you install a new version of a module into a different location, core happily keeps using the old one until you happen to clear this cache...
This reminds me a lot of bugs we had in update_status where we had to check the ctime on .info files to notice if a newer version was installed and clear various caches... :(
#5
Another bit of info... looking closely at function system_update_files_database(), I see this:
<?php...
if (isset($files[$file->name]) && is_object($files[$file->name])) {
// Keep the old filename from the database in case the file has moved.
$old_filename = $file->filename;
...
?>
cvs blame points here: #147000: Rewrite module_rebuild_cache() and system_theme_data()
I need to read that issue to figure out WTF this old_filename business is a good idea...
#6
Ok, #5 and the link to #147000 was a red herring. We're actually updating {system}.filename correctly in that case. See also #48025: System table not updated when moving modules.
HOWEVER, the bug is that when this happens, we leave the system_list cache broken. So, here's a patch that seems to work fine in my testing. We don't want to always clear this cache when we hit this function, since we'd be clearing it all the time. Therefore, I added code to remember if we hit the special case where a module moves directories, and only call system_list_reset() if that happened.
#7
Looks good to me.
#8
Bot's now happy. Note: I think it's basically impossible given out existing test framework to write a test for this case. :( So, we just have to rely on testing this manually at this point...
#9
The issue I was thinking of as soon as I saw this was #651086: Cache clearing is an ineffective mess in module_enable() and system_modules_submit() - which I now see is also mentioned above, and is indeed a different issue. However, in the patch there, as part of an overall effort to fix a bunch of things with broken caches, we have this:
@@ -2352,6 +2345,9 @@ function system_rebuild_theme_data() {ksort($themes);
system_get_files_database($themes, 'theme');
system_update_files_database($themes, 'theme');
+ // Before returning, reset the system_list() cache, since it stores the
+ // contents of theme .info files which may now be out of date.
+ system_list_reset();
return $themes;
}
So basically, in one of the two places that calls system_update_files_database(), we already have a totally separate reason for wanting to clear this cache anyway...
You wrote: "We don't want to always clear this cache when we hit this function, since we'd be clearing it all the time" but I'm not sure what you mean by that. We only call it from system_rebuild_module_data() and system_rebuild_theme_data() as far as I can tell, which tend to be functions that don't get called that often, right?
I'm wondering if it would be just simpler (and more future-proof) to clear it here always, rather than trying to track when it's necessary to do so.
#10
@David_Rothstein: Well, in my testing, if I dvm() whenever I clear that cache, if we always do it when we hit that function, we clear the cache 3 times on each admin/modules page load, twice on the status report, twice on the available updates report, etc. :( Seemed woefully inefficient that way, so having a bit of logic to remember that we need this seemed worth doing...
#11
subscribing
#12
#6: 683988-6.reset_system_list_when_module_moves.patch queued for re-testing.
#13
Makes sense, code looks good, let's get this in.
#14
Chasing head :)
#15
The last submitted patch, 683988-14.reset_system_list_when_module_moves.patch, failed testing.
#16
#14: 683988-14.reset_system_list_when_module_moves.patch queued for re-testing.
#17
#18
system_get_files_database() isn't called often so I'm surprised we want to be smart about when the cache is flushed. Can't we just call system_list_reset()?
#19
@Dries Re: #18 -- Please see #10.
#20
Ah, I overlooked #10 so thanks for pointing that out. I'll investigate that some more this weekend -- I wonder if the behavior in #10 is due to another bug.
#21
Critical bump.
#22
It still isn't clear why we clear the cache 3 times on admin/modules page load, twice on the status report, twice on the available updates report, etc. This patch might be more complex than it ought to be. I don't feel this is RTBC until we better understand what is going on and what a proper fix might look like.
#24
Patch should at least be re-rolled with -up, impossible to tell what's changing where.
@Dries I think some of the proper fix is in the various aborted patches at #651086: Cache clearing is an ineffective mess in module_enable() and system_modules_submit() - we clear a lot of these caches multiple times.
#25
Re-rolled with -up. I looked back over #10, and while I agree it's woefully inefficient to be calling this so many times, it looks like we should be skipping this whole function rather doing internal checks as to whether to clear the cache or not. So re-rollled just with the cache clearing. Let's open a new issue to find out why it gets called so often.
#26
As part of the workaround that fixed #651086: Cache clearing is an ineffective mess in module_enable() and system_modules_submit(), we put this code in the form submit handler for the modules page:
<?phpcache_clear_all('system_list', 'cache_bootstrap');
?>
Doesn't this patch mean that can now be removed? Also, as a result of that code, I can no longer reproduce the original bug exactly - if you actually submit the modules page after installing the second version of the module it works fine, but the bug still occurs if you only visit the modules page (or just go to update.php directly), so it still seems like it needs a fix.
Clearing the cache a couple times in a row is annoying, but given that it's pretty inexpensive to regenerate that cache compared to the other things that are going on in system_rebuild_module_data() and system_rebuild_theme_data(), I think this is definitely OK - the real performance win would come from not calling the rebuild functions more than once in the first place (if we can solve that in the other issue).
#27
Yep, that looks duplicate now, added removal of that call to the patch. Agreed with the rest of David's comment as well.
#28
subscribe
#29
The patch works, and I verified (just because I'm paranoid) that removing that line indeed did NOT bring back the evil "toolbar-in-the-overlay" bug.... So looks like it's good to go.
#30
Committed to CVS HEAD.
#31
Committed to CVS HEAD.
#32
Automatically closed -- issue fixed for 2 weeks with no activity.