I haven't had a chance to test this on a clean install as yet but I thought I would post an issue to see if you had any thoughts.

The symptom I noticed was that I was no longer getting anything logged by the watchdog. Tracing it all through led me back to the the module_implements row of the cache_bootstrap table where watchdog was an empty array—in other words apparently no modules are implementing hook_watchdog. This is of course untrue—dblog, rules and devel all implement this on my site. I tried clearing the cache and rebuilding the registry without success. Grasping at straws I tried uninstalling xautoload because it was the last module I installed and sure enough the module_implements data in the cache_bootstrap table changed SIGNIFICANTLY (I diffed it and found 147 changes) and the watchdog array contained dblog, rules and devel—and my logs started filling up again.

Is there anything that this module is doing that should affect the module_implements table so drastically? I want to keep it on so I can use the configuration module but I can't deal with not having logs—also I'm wondering what other hooks it's affecting.

Thanks

Josh

Comments

donquixote’s picture

Is there anything that this module is doing that should affect the module_implements table so drastically?

I think any module enabling or disabling will get you a big diff in this cache. Even clearing the cache will do that.
This cache is completely emptied on module enable / disable and on cache clear, and then slowly filled up.

The hook_watchdog() will only fill up as soon as anything calls module_implements('watchdog').
And it is only written to the cache in module_implements_write_cache(). Which is called in drupal_page_ footer().

What you could do to investigate further:

function mymodule_init() {
  dpm(module_implements('watchdog'));
}

(doesn't have to be in hook_init(), that's just a reliable place to have this fire on every request)

sonictruth’s picture

Yes, I'm aware that the cache will get rebuilt on any cache clearing which also happens when modules are enabled/disabled. The main reason I mentioned all the changes in the cache is just because I figured if it was affecting hook_watchdog then maybe it's affecting other hooks as well.

I had already checked the results of module_implements('watchdog') with xautoload on and off and it reflected what was in the cache_bootstrap table. When xautoload is off it returns an array with 'dblog', 'rules' and 'devel'. When xautoload is on it returns an empty array.

I've since tested this in a clean install of Drupal and everything is fine with xautoload on so it must be something about this particular site that is causing the issue but it's definitely a collision of some sort with your module.

I will have to dig into it further. Are there any parts of xautoload that you can think of that will be directly affecting the cache_bootstrap table? This would be a good place to start digging.

donquixote’s picture

I don't know where this would be coming from.
xautoload does alter the module_implements stuff, but only for itself.
Maybe you could sprinkle some dpm() into the code in core that looks for hook implementations.

There is also a question when the module_implements() fires, if it fires too early in the request, before the respective *.module file is included. Related to that, you could check if the respective modules are correctly marked as "bootstrap" modules, if they need to be.

donquixote’s picture

Hi,
another theory that might help you dig further.

There is also a question when the module_implements() fires, if it fires too early in the request, before the respective *.module file is included.

What about:
1. Something goes wrong early in bootstrap, before the respective *.module files are loaded. xautoload could be involved in this error, but this might be totally unrelated to watchdog so far.
2. Some part of core thinks it's a good idea to log this error in watchdog.
3. The module_implements('watchdog') is rebuilt. Since the respective *.module files are not included, it does not find devel_watchdog() and dblog_watchdog() and rules_watchdog(). The incomplete hook implementation list is saved in the cache.

Let's find this asap so we can fix or close this bug!

donquixote’s picture

Another theory:
xautoload_module_implements_alter() triggers some other function calls, and these in turn trigger hook_module_implements_alter() again. So we get nested calls of hook_module_implements_alter(), two levels or more, and this might result in some weird behavior.

xautoload uses this hook for two purposes:
1. To put its own hooks into separate files.
2. To register some module-provided autoload stuff, when these modules have just been enabled, but before hook_modules_enabled() is fired.

donquixote’s picture

Btw, I am playing with
drush php-eval "print_r(module_implements('watchdog'));"
but I cannot reproduce the problem. It always shows all 4 implementations.

donquixote’s picture

Status: Active » Needs review

Still don't have a solid explanation, but it could be that it is fixed in 7.x-5.x, due to other changes.
Could you try?

donquixote’s picture

Status: Needs review » Postponed (maintainer needs more info)

Need more info.

donquixote’s picture

I am only now looking at the 7.x-4.x branch, particuparly the 7.x-4.1 and 7.x-4.5 releases.
The following looks suspicious:
(and it has been changed in 7.x-5.x)

function xautoload_module_implements_alter(&$implementations, $hook) {

  static $modules;
  if (!isset($modules)) {
    $modules = module_list();
  }

  // Some crazy stuff (like using l() in hook_enable()) can trigger hook
  // invocation on just-enabled modules, before xautoload has a chance to
  // register their namespaces. The only place to register these modules is
  // here.
  foreach ($implementations as $module => $group) {
    if (empty($modules[$module])) {
      // This module needs to be registered, to avoid a missing class error.
      xautoload()->extensionRegistrationService->registerExtensionsByName(array($module));
      xautoload()->cacheManager->renewCachePrefix();
      $modules[$module] = $module;
    }
  }

What I imagine could happen is that module_list() or some other piece of code triggers an error. This triggers the drupal error handler. This triggers watchdog. This triggers module_implements('watchdog'). This goes to hook_module_implements_alter() again.

Not sure what happens next. But it looks bad enough to me.

So, I recommend updating to 7.x-5.0 to avoid this.

donquixote’s picture

Title: xautoload changes module_implements data on cache_bootstrap » xautoload changes module_implements data on cache_bootstrap (Fixed in 7.x-5.x)
Version: 7.x-4.1 » 7.x-4.x-dev
Status: Postponed (maintainer needs more info) » Closed (won't fix)

I'd say, this is fixed in 7.x-5.x.
Not going to fix this in 7.x-4.x.

Not sure if this is "Fixed" or "Won't fix" then..
I hope that people reading this will get the point.