This is an odd issue.
Symptoms: Trying to create a profile that uses another as base, the installer fails while installing modules with an 'table watchdog' not found. The exact error is collateral damage, the issue is deeper. The sub profile doesn't have any dependencies at all, and are only installing the same modules as the base profile. The base profile installs without errors.
The attached patch fixes this (go on, have a look).
Analysis: Now, this is the hard part. However, some observations I did while debugging: the dblog modules is listed in the dependencies, and when the sub profile fails, it's installed quite late in the process (just before the profile itself), but when installing the base profile, it's installed much earlier. It seems that the fact that profiler_config_reduce() inadvertently reverses the dependencies when it adds the base profiles dependencies changes the order in which the modules are installed. This shouldn't really be a problem, as _module_build_dependencies() should ensure that no module is installed before its dependencies, but apparently it is anyway.
Now the interesting thing is that reverting the order of the dependencies in the base module info file, fixes the problem without this patch, and reverting them and applying the patch makes the install fail again. However, reverting the dependencies does not make the base profile fail (it doesn't care either way).
Speculation: It could be that the reason dblog fails is that there some module that does/triggers a watchdog in some of the hooks that's called between module_enable enables the module and it creates the table. Which is unhandy module interaction which is hard to do anything about, but ensure that the dblog module is enabled early. But if profiler reverses the dependencies for sub profiles, this becomes impossible.
| Comment | File | Size | Author |
|---|---|---|---|
| #4 | profiler-order.tgz | 1.62 KB | xen |
| profiler-reverse.patch | 667 bytes | xen |
Comments
Comment #1
q0rban commentedWow, this IS weird. Can you confirm that this bug still exists with the latest version of Drupal 7 and Profiler? Thanks.
Comment #2
xen commentedI've retested with 7.12 and profiler 7.x-2.x HEAD (d0137cb), and the issue is still the same. Meanwhile the profiles that surfaced the bug has changed enough to actually work in either case now, but that doesn't fix the underlying issue.
Without the this patch, looking in the watchdog after installing the base profile, shows a lot of messages about installing this module or other, while installing the sub-profile only shows four, as the dblog module is installed as one of the last. With the patch, the watchdog for the sub-profile matches the base profile.
One might argue that it's not a failure of profiler, as is it's most likely caused by missing dependencies (perhaps on required core modules, who remembers those?), or other misbehavior of the installed modules, but, you know, this being the real world, fixing the problem proper (or finding the time to figure out that really odd race condition) isn't always an option, and being able to work around a problem temporarily by carefully ordering the dependencies can be a godsend. So I think profiler should make the effort to keep the order of dependencies of the base profile.
Why the base profile didn't start failing when reversing its dependencies by hand, I don't know, but I'm guessing that the massaging profiler_config_reduce does to the dependencies array, does something that makes _module_build_dependencies work slightly differently.
Comment #3
q0rban commentedThanks for testing! Yes, I agree, this has me suspicious of other things than profiler, but I am also willing to fix it here. Would you be able to provide me with some steps to replicate it, or perhaps provide dumbed down versions of the profiles you are using that cause the issues? Thanks again for both the patch, and your time in testing. :)
Comment #4
xen commentedThe profiles I was experiencing the problem with isn't public yet.
I've tried to make an example, and while it shows that the order is different, the above patch doesn't do any difference.
Anyway, it's in the attached archive. You'll need to put profiler in the libraries dir of the sub profile and symlink the modules folder from the base profile to the sub profile, so they can see the same modules.
After an install, you can check the order with this long oneliner (which relies on mysqls habit of using the insert order when none other is specified):
drush php-eval "foreach (db_query('SELECT variables FROM watchdog WHERE message = \'%module module enabled.\' ORDER BY timestamp')->fetchCol() as \$vars) {\$vars = unserialize(\$vars); drush_print(\$vars['%module']);};"
Alternatively, one can add an error_log($module) to line 451 of includes/module.inc, and tail the error_log.
Comment #5
q0rban commentedI was unable to replicate this with your attachment. Steps I took:
I didn't receive any error that watchdog_table was not found.
Thanks for taking the time to put all that together for me! :) Did I do something wrong?
Comment #6
xen commentedNo, it doesn't fail. I guess that would require one of the modules to mess with a db table created by another, but not having the right dependencies.
You can use the long drush command i included earlier to see the installation order.
Alternatively, you can add debugging (drush_print_r, if you're using drush si) to print out $config['dependencies'] in profiler_system_info_alter() before and after the profiler_config_reduce to see that it reverses the order.
Comment #7
Chris Gillis commented