Closed (duplicate)
Project:
Drupal core
Version:
6.x-dev
Component:
update.module
Priority:
Critical
Category:
Bug report
Assigned:
Unassigned
Reporter:
Created:
4 Nov 2011 at 10:45 UTC
Updated:
30 Nov 2011 at 15:32 UTC
Hi,
Ever since the dawn of D6 I've been experiencing themes getting randomly disabled on most (if not all) of our Drupal 6 websites. Bizarrely, when this occurs default theme remains set, but all the settings no longer apply and if you go to the themes page you see all the "enabled" boxes unchecked. Usually this has no effect, or at worst, minor effect (like the search box disappearing in a Zen-based theme, or something stupid like that). Sometimes it has a catastrophic effect, for example: #979912: Panels cache getting stuck, getting white screen on my homepage panel.
We have another site, not using Panels, that was suffering this occasional disabling of themes and it was critical there too, because the random disabling of themes caused a WSOD, which of course got the client on the phone pretty quick!
The problem was recurring and wouldn't go away. And because we'd all experienced it elsewhere (and knew many others had too) we decided to take things further. First off, we wrote a drush script to re-enable the theme if it went away. It looks like this:
/**
* Implementation of hook_drush_command().
*/
function cantos_drush_command() {
$items = array();
$items['cantos-theme'] = array(
'description' => "Ensures certain themes are enabled. Ensures the default theme is set to rubik.",
'aliases' => array('ct'),
);
return $items;
}
function drush_cantos_theme() {
drush_bootstrap(DRUSH_BOOTSTRAP_DRUPAL_SITE);
// Make sure rubik and cantoscmt_theme are enabled
$themes = array('rubik', 'cantoscmt_theme');
// Populate a list of extensions
$extensions = drush_get_extensions();
// Check the status of the themes, enable if not enabled
foreach($extensions as $extension) {
if (in_array($extension->name, $themes)) {
$status = drush_get_extension_status($extension);
if ($status != "enabled") {
drush_pm_enable($extension->name);
watchdog('theme_watcher', dt('Had to enable theme !theme', array('!theme' => $extension->name)));
}
}
}
// Let's make sure rubik is the default theme
$theme = variable_get('theme_default', FALSE);
if ($theme == "rubik") {
return true;
} else {
drush_vset("theme_default", "rubik");
watchdog('theme_watcher', dt("The default theme was !theme. Changed to rubik.", array('!theme' => $theme)));
}
}
We ran that on a frequent cron, so at least we knew the site would never be down for more than a couple of minutes. We also started adding debug lines based on the theory outlined here:
http://drupal.org/node/979912#comment-4015666
We started simply logging in watchdog whenever any functions were called that might result in themes being loaded from .info files instead of from the database. We very quickly found list_themes() was not at fault, but in fact it happened when system_theme_data() was called, always - see #1226644: Themes being disabled - not done by an Administrator
So we added debug lines in core to capture every single instance of system_theme_data() being called. We also set the capture of a backtrace and had _system_theme_data() (the actual function that loads theme data from files instead of from the database) report when it had been called.
Traps set, sit and wait.
We were rewarded on 23rd October (I only just checked the logs) when we had a repeat of the problem. Here's what watchdog looked like:
cron 23.10.2011 - 07:00 Cron run completed. Anonymous
update 23.10.2011 - 07:00 Attempted to fetch information about all available ... Anonymous
theme_watcher 23.10.2011 - 07:00 Had to enable theme cantoscmt_theme Anonymous
theme_watcher 23.10.2011 - 07:00 Called _system_theme_data() - theme information ... Anonymous
theme_watcher 23.10.2011 - 07:00 Called _system_theme_data() - theme information ... Anonymous
theme_watcher 23.10.2011 - 07:00 Called _system_theme_data() - theme information ... Anonymous
theme_watcher 23.10.2011 - 07:00 Backtrace: Array ( [0] => Array ( ... Anonymous
theme_watcher 23.10.2011 - 07:00 Called update_get_projects() which in turn called ... Anonymous
In and around that were a pile of notices, caused by #1006938: Remove PHP warnings from legacy PHP4 XML parser for new update status release history XML, just FYI.
So we can see the turn of events:
1. Cron starts
2. Update module runs, calls update_get_projects() which calls system_theme_data()
Backtrace - just before the call to system_theme_data() - looks like this:
Array
(
[0] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/modules/update/update.fetch.inc
[line] => 41
[function] => update_get_projects
[args] => Array
(
)
)
[1] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/modules/update/update.module
[line] => 382
[function] => _update_refresh
[args] => Array
(
)
)
[2] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/modules/update/update.module
[line] => 301
[function] => update_refresh
[args] => Array
(
)
)
[3] => Array
(
[function] => update_cron
[args] => Array
(
)
)
[4] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/includes/module.inc
[line] => 482
[function] => call_user_func_array
[args] => Array
(
[0] => update_cron
[1] => Array
(
)
)
)
[5] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/includes/common.inc
[line] => 2747
[function] => module_invoke_all
[args] => Array
(
[0] => cron
)
)
[6] => Array
(
[file] => /var/www/cantoscmt_prod_build_15/www/cron.php
[line] => 10
[function] => drupal_cron_run
[args] => Array
(
)
)
)
3. _system_theme_data() is called three times in a row (perhaps not by update module every time?)
4. Our own command notices the themes have gone away and intervenes
This all happens within milliseconds, so it seems the cause is clear. We can see *what* is happening, but I'm still none the wiser as to *why*.
I guess we need a backtrace in those _system_theme_data() calls too?
Anyway, there's definitely a bug here, because of the possible consequences I'd definitely call it critical, AFAIK this code still exists in Drupal 7, so it is *likely* to be affected too (e.g. we ought to take notice!) and I've narrowed it down to a very specific set of circumstances. I'm prepared to admit the Update module might just be in the wrong place at the wrong time and the issue may be with the core theme system instead, but leaving our "traps" running to see what falls in next.
Comments
Comment #0.0
greg.harveyAdding clarity.
Comment #1
greg.harveyTiny update. I've applied the latest patch in #1006938: Remove PHP warnings from legacy PHP4 XML parser for new update status release history XML to reduce the noise in watchdog significantly and I've also added a backtrace right after recording we have called
_system_theme_data()so where we have multiple calls we'll be able to identify which function called them.And the drush notice I originally mentioned is definitely not related, I saw we call that function in our theme watcher and it's a separate issue - edited out of original issue for clarity.
Comment #2
greg.harveyFollowing on from this, adding check noted here:
http://drupal.org/node/979912#comment-5293076
Possibly related, possibly not.
Comment #3
greg.harveyOK, further follow-up. Latest blip, 19th November, shows this:
Sequence of events is, once again:
1. Cron starts
2. Update module runs, calls
update_get_projects()which callssystem_theme_data()- backtrace as before3. Cron runs the drush theme checker we created
4. Theme checker itself actually fires
_system_theme_data()(that was the second run we noted last time)5. This time we get a bunch of duplicate entry warnings from PHP, for example:
6. Theme checker enables Rubik then runs again
7. Second run of theme checker (third execution of
_system_theme_data()) enables the custom theme, this time no duplicate warningsSo, what seems to be happening is sometimes (perhaps randomly, but so far whenever Update Status calls it) the
system_theme_data()function fails to safely complete, leaving the system table in a corrupted state. Firing thesystem_theme_data()again seems to force it to sort itself out, but information about which themes were enabled seems to get lost in the process.This would make sense. If the data is corrupted in the first pass then it needs to be reloaded from info files which have no notion of enabled or disabled.
Certainly, we're seeing this sequence:
At some point during that sequence the system table is corrupted, but silently. The next time
system_theme_datathe corruption is "visible" by way of PHP duplicate warnings, and the theme data is restored, however the enabled/disabled information is not restored - it can't be.So themes remain in a semi-corrupted, semi-disabled state until someone or some other application comes along and properly enables them.
Comment #4
jbrauer commentedThis issue and a patch are at #147000: Rewrite module_rebuild_cache() and system_theme_data() Please test and +1 so we can get it fixed in core.
Comment #4.0
jbrauer commentedFurther clarification and factual error.