Tricky cache invalidation bug when storing cache_bootstrap in Memcached

Hello,

At my organization, we use Memcached as backend for all Drupal bins (except cache_form), including cache_bootstrap. For this, we rely on the Memcache module (development version, i.e. 7.x-1.x ). It is slightly patched for a specific need of ours (we deported the cache_clear_all() call detection in a is_called_by_cache_clear_all() function), but this does not impact the issue exposed here.

Having encountered some weird cache effects despite the use of "drush cc all" (i.e. drupal_flush_all_caches()), I have decided to study and document what happens when executing cache_clear_all("*", "cache_bootstrap", TRUE) and I finally encountered the bug I was looking for. Here is the result...

Explanation of the bug

Let's study what happens when either drush cache-clear or the Drupal UI end up executing cache_clear_all("*", "cache_bootstrap", TRUE):

cache_clear_all("*", "cache_bootstrap", TRUE)
  _cache_get_object('cache_bootstrap')->clear('*', TRUE);
    MemCacheDrupal::clear('*', TRUE);

The first condition gets evaluated to FALSE unless there was a problem connecting to the Memcached instances.

function clear($cid = NULL, $wildcard = FALSE) {
  if ($this->memcache === FALSE) {
    // No memcache connection.
    return;
  }

The second condition also gets evaluated to FALSE since the MEMCACHE_CONTENT_CLEAR constant is defined to 'MEMCACHE_CONTENT_CLEAR' (not '*') and the is_called_by_cache_clear_all() method returns TRUE only for calls to cache_clear_all() without any argument.

if ($cid == MEMCACHE_CONTENT_CLEAR || $this->is_called_by_cache_clear_all()) {
  // Update the timestamp of the last global flushing of this bin.  When
  // retrieving data from this bin, we will compare the cache creation
  // time minus the cache_flush time to the cache_lifetime to determine
  // whether or not the cached item is still valid.
  $this->cache_content_flush = time();
  $this->variable_set('cache_content_flush_' . $this->bin, $this->cache_content_flush);
  /* code stripped for the sake of clarity */
}

While the code shown above is not executed in our study, it is to be noted the cache flush triggered by a call to cache_clear_all() would rely on a timestamp variable named cache_content_flush_cache_bootstrap.

We enter in the third condition since $wildcard is TRUE; $cid is explicitly modified to '' so that we enter the "if (empty($cid))" condition:

if (empty($cid) || $wildcard === TRUE) {
  // system_cron() flushes all cache bins returned by hook_flush_caches()
  // with cache_clear_all(NULL, $bin); This is for garbage collection with
  // the database cache, but serves no purpose with memcache. So return
  // early here.
  if (!isset($cid)) {
    return;
  }
  elseif ($cid == '*') {
    $cid = '';
  }
  if (empty($cid)) {

We can now read that the wildcard invalidation relies on a cache_flush_cache_bootstrap variable (not to be confused with cache_content_flush_cache_bootstrap); $this->flushed and $this->cache_flush both end up with the flush time value because we configured cache_lifetime to 0.

// Update the timestamp of the last global flushing of this bin.  When
// retrieving data from this bin, we will compare the cache creation
// time minus the cache_flush time to the cache_lifetime to determine
// whether or not the cached item is still valid.
$this->cache_flush = time();
$this->variable_set("cache_flush_$this->bin", $this->cache_flush);
$this->flushed = min($this->cache_flush, time() - $this->cache_lifetime);

However, the cache_flush_cache_bootstrap variable is not set through the usual variable_set() global function; instead, the MemcacheDrupal class provides its own variable_set() method:

/**
 * Re-implementation of variable_set() that writes through instead of clearing.
 */
function variable_set($name, $value) {
  global $conf;
 
  db_merge('variable')
    ->key(array('name' => $name))
    ->fields(array('value' => serialize($value)))
    ->execute();
  // If the variables are cached, get a fresh copy, update with the new value
  // and set it again.
  if ($cached = cache_get('variables', 'cache_bootstrap')) {
    $variables = $cached->data;
    $variables[$name] = $value;
    cache_set('variables', $variables, 'cache_bootstrap');
  }
  // If the variables aren't cached, there's no need to do anything.
  $conf[$name] = $value;
}

This method takes care to:

• update the variable table itself
• retrieve the variables cached in the cache_bootstrap bin, i.e. in this bin, i.e. it ends up calling the get method of that very same MemCacheDrupal instance:

    function get($cid) {
      $cache = dmemcache_get($cid, $this->bin, $this->memcache);
      return $this->valid($cid, $cache) ? $cache : FALSE;
    }

This method in turn calls valid(), which checks the flush timestamp against the previously set cache_flush attribute:

    // Items created before the last full wildcard flush against this bin are
    // invalid.
    elseif ($cache->created <= $this->cache_flush) {
      $cache = FALSE;
    }

so we end up with both valid() and get() returning FALSE, so the content of the cache_bootstrap bin is not updated with the new value of cache_flush_cache_bootstrap. Therefore, next calls to cache_get() will probably return adequate values because they rely on the global $conf array, but when treating the next HTTP request, the cached cache_bootstrap entries will still be considered valid whereas they should have been flushed. Moreover, even if cached variables had been modified, their "created" attributes may have ended with a higher value than cache_flush_cache_bootstrap, so it would not have worked either.

The rest of the code should not be executed (else statement + we set cache_lifetime to 0).

The analysis above was confirmed by a strace-based debugging, using:

strace -f -t -e read=2,3,4,5,6,7 -e write=2,3,4,5,6,7 drush php-eval 'drush_print("start"); cache_clear_all("*",
"cache_bootstrap", TRUE); drush_print("stop");' 2>&1

The fact that formerly cached variables are not altered the way they should be and that cache_flush_* variables may not be set as expected for future requests could explain many flush-related bugs, but I did not take the time to analyze all existing issues in detail.

First attempt at solving the issue

Since it appeared to be a simple problem of timestamp check, my first attempt to solve this issue was the following patch:

--- memcache.inc    2012-11-15 15:37:28.046671000 +0100
+++ memcache.inc    2012-12-27 10:24:37.832478000 +0100
@@ -215,8 +214,9 @@
         // retrieving data from this bin, we will compare the cache creation
         // time minus the cache_flush time to the cache_lifetime to determine
         // whether or not the cached item is still valid.
-        $this->cache_flush = time();
-        $this->variable_set("cache_flush_$this->bin", $this->cache_flush);
+        $flush_time = time();
+        $this->variable_set("cache_flush_$this->bin", $flush_time);
+        $this->cache_flush = $flush_time;
         $this->flushed = min($this->cache_flush, time() - $this->cache_lifetime);
  
         if ($this->cache_lifetime) {

=> we simply take care to call variable_set() before setting the flush_time.

However, things are not that simple: the bug described here is mostly due to the fact the Memcache module relies on Drupal variables to store various flush timestamps while variables may also get cached, thus inducing the need to frequently invalidate cached variables.
Since this looks counter-productive, the Memcache module prefers retrieving the currently cached data (through cache_get()), update the adequate variable and cache_set() it again. However, such an implementation of get-and-set is not atomic, and this may end up caching obsolete variables, be it in Memcached or any other storage backend. Also, it still implies two round-trips to another service (MySQL, Memcached, ...) except if cache_bootstrap is stored using APC (which sounds like a bad idea when using more than one PHP server).

Possible solutions

• modify the module so it does not rely anymore on Drupal variables; instead, each Memcached-based bin could store flush-related data into Memcached itself, using special keys.
• we could also keep the variables-based implementation but either:
  • explicitly delete cache_boostrap/variables through cache_clear_all('variables', 'cache_bootstrap', FALSE) then let the next Drupal bootstrap naturally cache again variables through variable_initialize() and its nifty lock
  • or rebuild variables like variable_initialize() does (perhaps calling it?), but we may end up rebuilding the cache several times per execution...

I am willing to implement the fix for this issue, but I would like to get the opinion of the current mainteners on it first, so that my patch can be integrated here/upstream.