With #2762157: [meta] Log to the logging service in place, we can now look at how Rules is executing on a real site, and that has revealed several issues.

What I'd like to address here is that it seems in many cases Rules is reacting to some events twice (but properly only executing the Rule once).

This is happening because Rules maintains a list of which events it needs to listen to, based on which events are currently being used by reaction rules. But Rules also creates bundle-specific events for entity CRUD events. For example, when the rules_entity_insert:node event is received, Rules will also generate a rules_entity_insert:node--bundle event (where bundle is 'article', 'page', etc) so that reaction rules may react only on these more-specific events. (Although, D8 does not yet have a way to restrict the bundle in the UI when creating the Rule).

The problem comes now that we have two events, because our registered reaction rules may (and probably DO) only respond to one of them. Rules mistakenly assigns an empty RulesComponent to the unused event, then executes that component (which has no effect).

The fix is simple. Patch attached.

Comments

TR created an issue. See original summary.

tr’s picture

Issue tags: +Needs tests

I think we need a test to demonstrate the problem and prove the solution. And/or a modification to existing test cases. This problem obviously wasn't noticed before logging was implemented, which means our existing tests are insufficient for this situation.

tr’s picture

The first patch is a test-only patch which should fail - this demonstrates the problem.

The other patch contains the test and the fix, this should pass, showing that the fix corrects the problem.

  • TR committed b6c0b38 on 8.x-3.x
    Issue #3105760 by TR: Empty Rules are firing
    
tr’s picture

Status: Needs review » Fixed

Committed.

jonathan1055’s picture

Unfortunately, the commit in this issue is the cause of #3106316: Scheduler Rules integration - failures at Core 8.7 - Rules cache update problem. I'm not saying that Rules is at fault, and I have not yet found any solution, either as a fix to Scheduler Rules Integration or to Rules code. However, moving the line $results[$event_id] = RulesComponent::create($action_set); inside the conditional on if ($configs) has caused the problem. If that single line is moved back out of the conditional block, all works fine and nodes which satisfy Scheduler condtions can be editted OK.

It seems that the actual problem is one of how the cache gets updated. In the failure cases we get

Drupal\Core\Entity\EntityStorageException
SQLSTATE[21S01]: Insert value list does not match column list:
1136 Column count doesn't match value count at row 1:
INSERT INTO {cache_rules} (cid, expire, created, tags, checksum, data, serialized) VALUES () ON DUPLICATE KEY UPDATE cid = VALUES(cid), expire = VALUES(expire), created = VALUES(created), tags = VALUES(tags), checksum = VALUES(checksum), data = VALUES(data), serialized = VALUES(serialized); Array()
in Drupal\Core\Entity\Sql\SqlContentEntityStorage->save() (line 847 of core/lib/Drupal/Core/Entity/Sql/SqlContentEntityStorage.php

which looks like empty data is being passed to the SQL query. So I looked at the backtrace

Drupal\Core\Database\Query\Upsert->execute() (Line: 263)
Drupal\Core\Cache\DatabaseBackend->doSetMultiple(Array) (Line: 193)
Drupal\Core\Cache\DatabaseBackend->setMultiple(Array) (Line: 112)
Drupal\rules\Engine\RulesComponentRepository->getMultiple(Array, 'rules_event') (Line: 140)

and in RulesComponentRepository::getMultiple() we have conditional logic on $cids_missing. It is that final call to $this->cacheBackend->setMultiple($cache_items) which causes the error.

Here is the source code for Scheduler Rules Integration.

Because it works OK in 8.8 and 8.9 maybe the SQL backend layer is doing something differently? I am stumped as to how to proceed with this, so any suggestions will be very welcome.

tr’s picture

Yes, that's the same error I was seeing in #3104328-10: Move list builders from D8RE into Rules, which is why I removed the enable/disable Rule button from the list builders before I committed them. I would get that DB error after disabling, unless I manually cleared the cache before I tried to execute any Rules. I was seeing that error on 8.7 - I didn't test it on 8.8 or 8.9.

So I'm pretty sure it IS a problem with Rules, I just don't know exactly what is causing the problem right now. I suspected it was triggered due to the change I made to the EventComponentResolver in #3104328: Move list builders from D8RE into Rules, and not due to the above patch, but I haven't bisected the problem to figure out exactly what caused it.

jonathan1055’s picture

Status: Fixed » Needs review
StatusFileSize
new1.04 MB
new1.28 KB

Thanks for the feedback, really helpful, and confirming that it is a Rules problem has encouraged me to investigate further. I think I have solved the problem and can also explain why it works OK in 8.8 and 8.9 but fails in 8.7

In my manual testing I have created one reaction rule, event is on saving existing content, and not filtered by content type.

After clearing the cache there is always at least one new entry in $cache_items in RulesComponentRepository::getMultiple so calling cacheBackend->setMultiple($cache_items) will always be OK. With the old code before this commit to only fire rules where a $config exists, on executing the rule a second time without clearing the cache, the executed component is retrieved from cache and the "missing" $cid is got from resolvers[$provider]->getMultiple (EventComponentResolver.php::getMultiple in this case) which would always return something, so there was always values in $cache_items which meant that cacheBackend->setMultiple($cache_items) would run OK.

Now, with the new code in EventComponentResolver.php::getMultiple to only store results where there are $configs, we do not get back anything for the item which is not already in the cache. $resolved_results is empty, which means $cache_items is empty and cacheBackend->setMultiple($cache_items) fails. In case I have not explained the above very clearly I have uploaded a pdf with output debug and annotations.

I think the solution is that in RulesComponentRepository::getMultiple() we only call cacheBackend->setMultiple if $cache_items is not empty. Or alternatively wrap the whole section with a conditional on $resolved_results not being empty. I have attached a patch for this.

The reason it does not fail in core 8.8 and 8.9 is that DatabaseBackend::doSetMultiple() now has a check to exit early if $values is empty, but this is not in the 8.7 code.

For info, I don't think it was related to #3104328: Move list builders from D8RE into Rules as that commit was 13th January but I found the fault on 10th.

tr’s picture

Good work! Can you open a new issue and copy everything you said over there? I would like a new issue so you will get credit for it. It doesn't sound like we will have to reverse anything made in this commit.

jonathan1055’s picture

Status: Needs review » Fixed

I have created #3108494: Exception when updating cache with empty data
Setting this issue back to Fixed.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.