Rules might be triggered too early in the bootstrap

Manually empty cache and cache_* tables in the database helped me.

Came here from #2161847: Fatal error: Unsupported operand types in rules.module on line 227...

Tried debugging to syslog

function rules_config_load_multiple($names = array(), $conditions = array()) {
  if (!function_exists('entity_load_multiple_by_name')) error_log(commerce_devel_printable_backtrace(debug_backtrace())); // Bug i get you!
  return entity_load_multiple_by_name('rules_config', $names, $conditions);
}

or to watchdog

function rules_config_load_multiple($names = array(), $conditions = array()) {
  if (!function_exists('entity_load_multiple_by_name')) watchdog('debug', commerce_devel_printable_backtrace(debug_backtrace()));
  return entity_load_multiple_by_name('rules_config', $names, $conditions);
}

but when i had my spies in place i could not reproduce. Maybe this helps someone else.

OK gotcha: So we have:
* somthing throws a notice in early bootstrap (here language negotiation)
* rules fires a watchdog event
* and does some recuild - but it's too early for this!

Setting to critical, this causes hard to track WSODs.

PHP Fatal error:  Call to undefined function entity_load_multiple_by_name() in .../sites/all/modules/rules/rules.module on line 830
RulesEventSet::rebuildEventCache() rules.module:355
rules_get_cache('event_watchdog') rules.module:995
rules_invoke_event('watchdog', Array) events.inc:180
rules_watchdog(Array) 
call_user_func_array('rules_watchdog', Array) module.inc:866
module_invoke('rules', 'watchdog', Array) bootstrap.inc:1735
watchdog('php', '%type: !message in %function (line %line of %file). Backtrace:<br/>!backtrace', Array, 4) commerce_devel.module:345
_commerce_devel_log_error(Array, ) commerce_devel.module:214
_commerce_devel_error_handler(2, 'Attempt to assign property of non-object', '/var/www/virtual/renner/html/development/code/_core/includes/language.inc', 499, Array) language.inc:499
language_initialize('language') bootstrap.inc:2662
drupal_language_initialize() shield.module:98
shield_set_status() shield.module:151
shield_get_status() shield.module:159
shield_boot() 
call_user_func_array('shield_boot', Array) module.inc:866
module_invoke('shield', 'boot') bootstrap.inc:1076
bootstrap_invoke_all('boot') bootstrap.inc:2488
_drupal_bootstrap_page_header() bootstrap.inc:2251
drupal_bootstrap(7) index.php:20

@axel.rutz Thanks for the debug line: I ran your debug and this is the backtrack I got.

Array
(
    [0] => Array
        (
            [file] => /path/to/html/sites/all/modules/contrib/rules/includes/rules.plugins.inc
            [line] => 764
            [function] => rules_config_load_multiple
            [args] => Array
                (
                    [0] =>
                    [1] => Array
                        (
                            [plugin] => reaction rule
                            [active] => 1
                        )

                )

        )

    [1] => Array
        (
            [file] => /path/to/html/sites/all/modules/contrib/rules/rules.module
            [line] => 357
            [function] => rebuildEventCache
            [class] => RulesEventSet
            [type] => ::
            [args] => Array
                (
                )

        )

    [2] => Array
        (
            [file] => /path/to/html/sites/all/modules/contrib/rules/rules.module
            [line] => 999
            [function] => rules_get_cache
            [args] => Array
                (
                    [0] => event_watchdog
                )

        )

    [3] => Array
        (
            [file] => /path/to/html/sites/all/modules/contrib/rules/modules/events.inc
            [line] => 180
            [function] => rules_invoke_event
            [args] => Array
                (
                    [0] => watchdog
                    [1] => Array
                        (
                            [type] => em_user
                            [message] => Smart IP language detected <pre>@location</pre>
                            [variables] => Array
                                (
                                    [@location] =>
                                )

                            [severity] => 7
                            [link] =>
                            [user] => stdClass Object
                                (
                                    [uid] => 0
                                    [hostname] => 127.0.0.1
                                    [roles] => Array
                                        (
                                            [1] => anonymous user
                                        )

                                    [cache] => 0
                                )

                            [uid] => 0
                            [request_uri] => http://index.php
                            [referer] =>
                            [ip] => 127.0.0.1
                            [timestamp] => 1411749090
                        )

                )

        )

    [4] => Array
        (
            [function] => rules_watchdog
            [args] => Array
                (
                    [0] => Array
                        (
                            [type] => em_user
                            [message] => Smart IP language detected <pre>@location</pre>
                            [variables] => Array
                                (
                                    [@location] =>
                                )

                            [severity] => 7
                            [link] =>
                            [user] => stdClass Object
                                (
                                    [uid] => 0
                                    [hostname] => 127.0.0.1
                                    [roles] => Array
                                        (
                                            [1] => anonymous user
                                        )

                                    [cache] => 0
                                )

                            [uid] => 0
                            [request_uri] => http://index.php
                            [referer] =>
                            [ip] => 127.0.0.1
                            [timestamp] => 1411749090
                        )

                )

        )

    [5] => Array
        (
            [file] => /path/to/html/includes/module.inc
            [line] => 866
            [function] => call_user_func_array
            [args] => Array
                (
                    [0] => rules_watchdog
                    [1] => Array
                        (
                            [2] => Array
                                (
                                    [type] => em_user
                                    [message] => Smart IP language detected <pre>@location</pre>
                                    [variables] => Array
                                        (
                                            [@location] =>
                                        )

                                    [severity] => 7
                                    [link] =>
                                    [user] => stdClass Object
                                        (
                                            [uid] => 0
                                            [hostname] => 127.0.0.1
                                            [roles] => Array
                                                (
                                                    [1] => anonymous user
                                                )

                                            [cache] => 0
                                        )

                                    [uid] => 0
                                    [request_uri] => http://index.php
                                    [referer] =>
                                    [ip] => 127.0.0.1
                                    [timestamp] => 1411749090
                                )

                        )

                )

        )

    [6] => Array
        (
            [file] => /path/to/html/includes/bootstrap.inc
            [line] => 1742
            [function] => module_invoke
            [args] => Array
                (
                    [0] => rules
                    [1] => watchdog
                    [2] => Array
                        (
                            [type] => em_user
                            [message] => Smart IP language detected <pre>@location</pre>
                            [variables] => Array
                                (
                                    [@location] =>
                                )

                            [severity] => 7
                            [link] =>
                            [user] => stdClass Object
                                (
                                    [uid] => 0
                                    [hostname] => 127.0.0.1
                                    [roles] => Array
                                        (
                                            [1] => anonymous user
                                        )

                                    [cache] => 0
                                )

                            [uid] => 0
                            [request_uri] => http://index.php
                            [referer] =>
                            [ip] => 127.0.0.1
                            [timestamp] => 1411749090
                        )

                )

        )

    [7] => Array
        (
            [file] => /path/to/html/sites/all/modules/custom/em_user/includes/language_negotiation.inc
            [line] => 16
            [function] => watchdog
            [args] => Array
                (
                    [0] => em_user
                    [1] => Smart IP language detected <pre>@location</pre>
                    [2] => Array
                        (
                            [@location] =>
                        )

                    [3] => 7
                )

        )

    [8] => Array
        (
            [file] => /path/to/html/includes/language.inc
            [line] => 450
            [function] => em_user_get_language
            [args] => Array
                (
                    [0] => Array
                        (
                            [en] => stdClass Object
                                (
                                    [language] => en
                                    [name] => Canada
                                    [native] => Canada
                                    [direction] => 0
                                    [enabled] => 1
                                    [plurals] => 0
                                    [formula] =>
                                    [domain] =>
                                    [prefix] => ca
                                    [weight] => 0
                                    [javascript] =>
                                )

                            [en-US] => stdClass Object
                                (
                                    [language] => en-US
                                    [name] => USA
                                    [native] => USA
                                    [direction] => 0
                                    [enabled] => 1
                                    [plurals] => 0
                                    [formula] =>
                                    [domain] =>
                                    [prefix] => us
                                    [weight] => 0
                                    [javascript] =>
                                )

                        )

                )

        )

    [9] => Array
        (
            [file] => /path/to/html/includes/language.inc
            [line] => 490
            [function] => language_provider_invoke
            [args] => Array
                (
                    [0] => em_user
                    [1] => Array
                        (
                            [callbacks] => Array
                                (
                                    [language] => em_user_get_language
                                )

                            [file] => sites/all/modules/custom/em_user/includes/language_negotiation.inc
                        )

                )

        )

    [10] => Array
        (
            [file] => /path/to/html/includes/bootstrap.inc
            [line] => 2669
            [function] => language_initialize
            [args] => Array
                (
                    [0] => language
                )

        )

    [11] => Array
        (
            [file] => /path/to/html/includes/bootstrap.inc
            [line] => 2262
            [function] => drupal_language_initialize
            [args] => Array
                (
                )

        )

    [12] => Array
        (
            [file] => /path/to/drush/includes/bootstrap.inc
            [line] => 944
            [function] => drupal_bootstrap
            [args] => Array
                (
                    [0] => 7
                )

        )

    [13] => Array
        (
            [file] => /path/to/drush/includes/bootstrap.inc
            [line] => 185
            [function] => _drush_bootstrap_drupal_full
            [args] => Array
                (
                )

        )

    [14] => Array
        (
            [file] => /path/to/drush/includes/bootstrap.inc
            [line] => 308
            [function] => drush_bootstrap
            [args] => Array
                (
                    [0] => 5
                    [1] => 6
                )

        )

    [15] => Array
        (
            [file] => /path/to/drush/drush.php
            [line] => 81
            [function] => drush_bootstrap_to_phase
            [args] => Array
                (
                    [0] => 6
                )

        )

    [16] => Array
        (
            [file] => /path/to/drush/drush.php
            [line] => 61
            [function] => _drush_bootstrap_and_dispatch
            [args] => Array
                (
                )

        )

    [17] => Array
        (
            [file] => /path/to/drush/drush.php
            [line] => 16
            [function] => drush_main
            [args] => Array
                (
                )

        )

)

So mine is language negotiation related too it seems.

Maybe I've configured the hook wrong (my worry).

// @file ./em_user.module

/**
 * Implements hook_language_negotiation_info().
 */
function em_user_language_negotiation_info() {
  return array(
    'em_user' => array(
      'callbacks' => array(
        'language' => 'em_user_get_language',
      ),
      'weight' => -5,
      'name' => t('User Smart IP'),
      // NOTE: The callback cannot be in this file, unless you specifically include it.
      // Language detection runs before Drupal Bootstrap completes.
      'file' => drupal_get_path('module', 'em_user') . '/includes/language_negotiation.inc',
      'description' => t('Determine the language from Smart IP detection.'),
    ),
  );
}


// @file ./includes/language_negotiation.inc
/**
 * Callback for hook_language_negotiation_info().
 *
 * @see http://www.iso.org/iso/country_codes/iso_3166_code_lists/country_names_and_code_elements.htm
 */
function em_user_get_language() {
  // Verify that a URL has been set.
  // require_once DRUPAL_ROOT . '/includes/common.inc';
  // require_once DRUPAL_ROOT . '/includes/file.inc';
  // drupal_load('module', 'smart_ip');
  // $location = smart_ip_get_current_visitor_location_data();

  // Turned off temporarily to test bug with files saving.
  watchdog('em_user', 'Smart IP language detected <pre>@location</pre>', array('@location' => print_r($_SESSION, TRUE)), WATCHDOG_DEBUG);
  return;

  // Return early if no country code.
  if (empty($location['country_code'])) {
    return;
  }

  switch ($location['country_code']) {
    case 'US':
      return 'en-US';
      break;
    case 'CA':
      return 'en';
      break;
  }
}

For me personally, I encountered this error only when turning on and off modules, after applying the operands patch to fix the prior error. My site got the WSOD. Clear cache via Drush and all is well.

The fix in my case was to move a php plugin class object I was using in my custom module in conjunction with a function local to that module out of the boot hook and into init. Adjusting the weight of the module etc didn't seem to change anything.

Re-titling to reflect the general problem.

We've already got rules_event_invocation_enabled() in HEAD, so what about disabling it by default and only running Rules evaluation only *after* the initial hook init call?

So what about a patch like that?

Cool, i did not notice we already have that.
The patch in #10 looks solid. Lights are green.
THe biggest problem i can imagine is to miss rules invocations we might want.
So i support getting this in thus ffixing a major WTF and amending later if we need.

A minor issue is to document that behavior, i have no proposal where.

I've had this applied on a high traffic site that just went into production for a couple of days. So far so good, thanks @fago.

Awesome, I'd missed this one too. I have two sites (one high trafficed) where this issue appears. Will test Monday. Thanks everyone!

The patch fixes the problem mentioned in this issue, however wouldn't it be better to actually check the current bootstrap phase? Why do we need a custom switch?

This patch fails against 7.x-2.7. Here are the rejects

--- rules.module
+++ rules.module
@@ -1665,6 +1667,10 @@
 /**
  * Helper to enable or disable the invocation of rules events.
  *
+ * Rules invocation is disabled by default, such that Rules does not operate
+ * when Drupal is not fully bootstrapped. It gets enabled in rules_init() and
+ * rules_enable().
+ *
  * @param bool|NULL $enable
  *   NULL to leave the setting as is and TRUE / FALSE to change the behaviour.
  *
@@ -1672,7 +1678,7 @@
  *   Whether the rules invocation is enabled or disabled.
  */
 function rules_event_invocation_enabled($enable = NULL) {
-  static $invocation_enabled = TRUE;
+  static $invocation_enabled = FALSE;
   if (isset($enable)) {
     $invocation_enabled = (bool) $enable;
   }

I am using this patch for Drupal core
https://www.drupal.org/files/drupal-1081266-102-drupal_get_filename-D7.p...
see https://www.drupal.org/node/1285856 which uses watchdog().

When I clear the cache, the watchdog() triggers hook_watchdog() which is implemented by Rules module.
Rules then tries to perform some database actions, but since it is too early in the bootstrap, it will generate a fatal error.

I am relying on this patch and it will soon become a major issue if they commit that patch in drupal core.

The patch in #10 works fine and I would recommend applying it immediately.

@fubhy: The switch is already there, not invented here. Committed #10.

This broke Commerce completely, because we use %commerce_order in our menu paths, and loading the order triggers an event which refreshes the order.
This appears to be done before hook_init(), so it's no longer happening. Here's my explanation of the process in a previous issue:
https://www.drupal.org/node/2120421#comment-8176391

Interesting, commerce_cart_commerce_order_load() looks suspicious. Firing events when an order entity is just loaded sounds dangerous to me. Instead of implementing hook_commerce_order_load() commerce_cart should refresh orders explicitly on its page callbacks. Maybe that is not possible for some reason? Unfortunately the docs on commerce_cart_commerce_order_load() do not tell why this is done in an entity load hook.

@klausi
Commerce relies on the fact that the loaded order is always up to date. It has worked that way since the 2010 alphas, and changing it now would be a big BC break.

Hm, we cannot roll this back since you get fatal errors in the early Drupal bootstrap when Rules is invoked without a database. We cannot change commerce_cart_commerce_order_load() for backwards compatibility either.

Solution 1: introduce explicit commerce_cart_order_refresh() calls in commerce_cart module when they are actually needed (in page callbacks and whatever).
Solution 2: Check the current Drupal bootstrap phase as proposed by fubhy in Rules when rules_invoke_event() is called. If it is >= DRUPAL_BOOTSTRAP_LANGUAGE then we can actually invoke the event, otherwise we just dismiss it.

As I said, solution #1 is not an option, because other parts of the code (and other modules) also depend on the order being loaded refreshed.

yeah, I see that changing commerce order behaviour aka solution #1 is not an option.
However, I do not think solution #2 is either as it does not seem to me that the language bootstrap is enough for rules - thus it would be wrong and possibly lead to other issue.

So what about just adding a hook menu implementation to workaround the problem of hook_menu() being executed before hook_init() and moving it up, such that we are one of the first hooks being called. Then, we can enable rules event evaluation there in addition?

What do you mean by adding a hook menu implementation? Did you mean hook_boot()? hook_menu() is not invoked on runtime?

oh, no. I thought the issue is when building menu items, but it's actually in the menu item loader callbacks :-( So maybe doing the same within hook_menu_get_item_alter() would work then?

I just came across this. Also having trouble with commerce.

it's actually in the menu item loader callbacks

Same finding here. menu_set_custom_theme(); in _drupal_bootstrap_full() triggers the whole chain of loading menu items, those loading entities and so on.

How about enabling rules not in hook_init() but in the middle between hook_boot() and hook_init()?
This is possible due the fancy hook_stream_wrappers_alter().

That is quite obscure. I think we should try hook_menu_get_item_alter() as fago proposed, which is called right before _menu_translate() entity loading in the menu system. And we need a doc block that tells why the heck we need it, describing the Commerce case as example.

I agree with klausi - relying on just on the onobviously working stream alter would be quite confusing. If possible I'd prefer the hook_menu_get_item_alter way as well.

Patch with hook_menu_get_item_alter() + test case.

@klausi Shouldn't we implement hook_module_implements_alter() to ensure the rules implementation is fired before others? rules_install() even set's a high weight, so it's even more likely we're too late in hook_module_implements_alter().

The order of hook_menu_get_item_alter() does not matter because it is called before _menu_translate() (which will invoke the menu object loading) in menu_get_item().

So what we could do in addition is check drupal_get_bootstrap_phase() in rules_menu_get_item_alter() before messing with rules_event_invocation_enabled(). Currently with the patch this will not work:

// I'm a cool module and I want Rules to shut up.
rules_event_invocation_enabled(FALSE);
// I need something from the menu.
$item = menu_get_item();
// WTF ... Rules event invocation is enabled now?????

The order of hook_menu_get_item_alter() does not matter because it is called before _menu_translate() (which will invoke the menu object loading) in menu_get_item().

Not sure if I agree, is it really just about _menu_translate()? What about another module that implements hook_menu_get_item_alter() and which does entity loading?
While I agree that this fixes the current issue, it's not a "longterm" solution in terms "what could go wrong".
Thus I think implementing hook_menu_get_item_alter() still would be a good idea.

So what we could do in addition is check drupal_get_bootstrap_phase() in rules_menu_get_item_alter() before messing with rules_event_invocation_enabled().

Agreed, how about the solution in the attached patch?

This is has become "quite complex" - I still like the hook_stream_wrappers_alter() approach. Looks about similar failure prone while having less code.

Edit: Fixed formatting

Darn, creating new files using git apply always inserts carriage returns on my system.
Re-rolled patch.

Works for me, although I don't think the ordering of hook_menu_item_alter() is important. There can also be other hooks like hook_boot() or any hook called before hook_menu_item_alter() in the bootstrap where firing events is disabled and developers want to do so while loading entities.

So regardless what we do this can only be a band aid around the bleeding use case of Commerce; I don't think that enabling Rules event invocation even earlier in hook_stream_wrappers() is a good idea since the path is not initialized for example; might lead to other problems.

Assigning to fago.

Following

This seems like a case of changing default functionally in a minor release, to get the expected results: breaking anything that depends on it. First thing people notice is commerce.

If you are going to change default behavior, why not wait until a major release? Shouldn't this be recalled? The fix the commerce people are suggesting is to downgrade to Rules 2.7.

I agree that the module implements alter is a good idea and that we are doing it in the right place here. I hope that there are no more other hooks invoked too early in the bootstrap (which I strictly speaking would consider as core bug), except for hook_boot() which is documented and intended as such.

The patch looks great, just found the following:

+++ b/rules.module
@@ -9,9 +9,42 @@
+  $rules_init = &drupal_static(__FUNCTION__, FALSE);
+  $rules_init = TRUE;

This seems to be useless and should be removed.

If you are going to change default behavior, why not wait until a major release?

The "default behaviour" has led to various problems, that's why we improved it. I'd expect no further side-effects for this, so the benefits outweigh possible problems. But anyway, we usually wait ~1month without introducing any larger changes before tagging a release so that dev versions and changes can be tested upfront.

oh, figured what's rules_init static var is used for. Thus added a comment to it and commited it, thanks!

I think watchdog should still be removed from the early bootstrap rules hooks, because:

Even with this change, entity_get_info() could be called after rules was enabled, but then if watchdog() is called, then rules_watchdog() and therefore entity_get_info() is being called again, which due to some other core problem can lead to an incomplete schema cache and ultimately to the site failing.

Therefore it would be great to allow three states:

- allow rules_watchdog just when hook_init() is done

watchdog() is just so low-level that that is very important.

In case there is worry that messages are missed, they could be collected till hook_init().

It took me quite a while to finally deduce and realize this, but I'm being bitten by EXACTLY what Fabianx describes in #47.

entity_get_info is being called, and schemas are not "complete" - for example "node" has a "base table" of null under the schema_sql_fields.

I've got a watchdog() that's happening early in one of my custom modules. If I comment out the rules_invoke_event('watchdog') then everything works fine.

I can try and work on a patch if someone can point me in a direction, write some pseudo-code, etc.

#48:

The idea is simple (thought it might not be simple to understand):

- In rules_watchdog add:

function rules_watchdog() {
  $queued = &drupal_static(__FUNCTION__, array());

  if (!rules_hook_init_done()) {
    $queded[] = $log_entry;
    return;
  }

  // Normal rules_watchdog code.
}

- In rules_init:

rules_init_done(TRUE);
$queued = &drupal_static('rules_watchdog', array());
foreach ($queued as $log_entry) {
  rules_watchdog($log_entry);
}

and that should be it already.

One edge case is when the process terminates before hook_init(), though it might be questionable if its safe to invoke rules_watchdog then at all.

Even with this change, entity_get_info() could be called after rules was enabled, but then if watchdog() is called, then rules_watchdog() and therefore entity_get_info() is being called again, which due to some other core problem can lead to an incomplete schema cache and ultimately to the site failing.

I see - so the workaround to postpone watchdog-event stuff until the end of hook init is welcome. Also the approach outlined in #49 makes sense to me - patch welcome!