Our caching patterns are error prone

Here is a tentative patch.

Commented.

Note that the problem is neither Drupal 7 nor render cache specific. Here is a somewhat convoluted use case that shows this is reproducible with practically every Drupal. You need a text format that has two filters: one inlines the node title, the other queries a third party service. The whole thing is cacheable, of course.

1. User A saves the node.
2. User A begins viewing the node. It takes a bit of time.
3. User B does a quick fix on the node title.
4. User A's check_markup() saves the filtered node body with the wrong node title.

I needed this convoluted example because check_markup is fairly resilient against this sort of problem by using practically the whole source as a cache key. However, it can still be fooled. And, of course, the render cache can't do this.

Another example:

1. User A begins to watch an uncached menu tree block made out of book node titles.
2. User B changes a node title.
3. User A caches the menu tree with the wrong title.

And so on. Endless examples. All you need is a slow running process that gets hit by a save in the middle.

Here is a patch that still needs tests (edit: and documentation). It has the render cache and check_markup converted, eventually needs every cache_get / cache_set pair converted. The API change is extension , ie if you dont change a thing then your code works the same as before (albeit still race prone).

Added a ton of comments. WIll add a test later.

This versioning patch won't work:

function system_test_increment_timestamp() {
  // Increment an integer.
  db_update('history')->expression('timestamp', 'timestamp' + 1)->execute();
  // Wipe my bin clear.
  cache_clear_all('*', 'cache_mybin', TRUE);
}
function testRenderCacheRace() {
    $value = 1;
    db_insert('history')->fields(array('uid' => 1, 'nid' => 1, 'timestamp' => $value))->execute();
    $render_array = array(
      'text' => array('#markup' => $value),
      '#pre_render' => 'system_test_increment_timestamp',
      '#cache' => array(
        'cid' => 'history',
        'bin' => 'cache_mybin',
      ),
    );
    // Cache the render array and modify timestamp at the same time.
    drupal_render($render_array);
}

I only used history here because it's present in a standard install. See? By the time this drupal_render finishes, the value of timestamp is 2 but the render cache will contain 1.

To fight that, one would need to keep a list of recent deletions in a separate place -- as Damien said, a ban list -- and check on set against that. It's fairly horrible because set will need to take out a lock on the bin first then check against the ban list and then run the db_merge. But it requires less API changes. And, hopefully, sets are rare.

This is the ban list patch. Note that I have not added locking to set() and clear() because that would need to be bin-wide (or so I think) and so now the race window is collapsed into the time between the two queries in set. That's certainly a lot better -- if not perfect -- than having the window thrown wide open (the time of rendering a node).

I think this is a good step ahead. We can try to do better in Drupal 8.

Less code, more comments. Lot more comments. Shows very cleanly what's the difference between the two tests.

Edit: this patch can be made better by testing for >= REQUEST_TIME in set(). It's still not ideal, will post more tomorrow.

Another attempt -- it only checks for clears if there was a failed get before. And it uses microseconds.

This one uses a double instead of a float (sigh). Also it matches the clears in PHP because it's impossible to match 'em in SQL. There won't be many if at all.

Here is another attempt, I hope this one passes. The CacheClearCase needed to be patched and that caused the patch to inflate a little. That's not a biggie. I have put back the clear-matching into SQL by using an evil trick: I store a LIKE pattern into the column and match $cid against that. It works.

andypost asked for a summary of the patch's doings.

1. it stores in an SQL table for a short period time when a cache_clear_all() was fired.
2. it stores in a static the timestamp when a cache_get failed.
3. In set it checks for clears since the last failed get and skips storing the cache in this case.

Edit: note that there is still a very short race window open between the db_query and the db_merge in set() but it's small enough to not worry me really.

Edit2: the whole issue builds on the presumption that if I add caching to the processing of some object then I will add cache clearing code to the saving of said object. This presumption tends to be true, otherwise you have stale caches.

Yes! I figured out how to make the race totally go away by going back to the idea of nuking the cache after the act.

Note: the performance hacks module (code here) adds render caching to nodes already. It's the poster child of this issue: on node update and delete it issues a cache_clear_all and it caching to node_view.

I tested upgrade and there is an upgrade test too so I am not sure what did you hit. I moved the upgrade into it's own if table exists just to make sure.