With authcache enabled, cache_page in memcache doesn't get cleared by drush cc all [#2015197]

With authcache enabled, cache_page in memcache doesn't get cleared by drush cc all

To verify this, I've tested 4 scenarios (in all cases anon page caching set to be handled by Drupal core).

1) cache_page in the db (no authcache or memcache)

Result: cc all removes cache_page entries

2) cache_page in memcache (no authcache)

Result: cc all removes cache_page entries

3) cache_page in memcache with authcache enabled

Result: cc all DOES NOT remove cache_page entries

4) cache_page in the db with memcache and authcache enabled

Result: cc all removes cache_page entries

This is not a case of leaving an expired entry in the cache bin (as cache_get will return expired entries, see https://drupal.org/node/534092), as the expiry date is in the future. It seems that authcache is preventing the cache_page being cleared.

Here are the actual tests; I'm checking for the presence of an entry in cache_page, but we only want to see the metadata so the actual cache entry itself's being thrown away.

1) cache_page in the db (no authcache or memcache)

Test:

mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~> curl -sIXGET http://d7sandbox.lucid/
HTTP/1.1 200 OK
Date: Sat, 08 Jun 2013 09:32:17 GMT
Server: Apache/2.2.14 (Ubuntu)
X-Powered-By: PHP/5.3.2-1ubuntu4.18
X-Drupal-Cache: MISS
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Sat, 08 Jun 2013 09:32:17 +0000
Cache-Control: public, max-age=300
ETag: "1370683937-0"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Vary: Cookie,Accept-Encoding
Transfer-Encoding: chunked
Content-Type: text/html; charset=utf-8

mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370683937
    [expire] => -1
    [serialized] => 1
    [created_h] => Sat, 08 Jun 2013 10:32:17 +0100
    [expire_h] => Thu, 01 Jan 1970 00:59:59 +0100
)
mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~>

Result: cc all removes cache_page entries

2) cache_page in memcache (no authcache)

config in settings.php

$conf['cache_backends'][] = 'sites/all/modules/memcache/memcache.inc';
//$conf['cache_backends'][] = 'sites/all/modules/authcache/authcache.inc'; 
$conf['cache_class_cache_page'] = 'MemCacheDrupal';
$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';
$conf['cache_default_class'] = 'MemCacheDrupal';

Test:


mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~> curl -sIXGET http://d7sandbox.lucid/
HTTP/1.1 200 OK
Date: Sat, 08 Jun 2013 09:28:43 GMT
Server: Apache/2.2.14 (Ubuntu)
X-Powered-By: PHP/5.3.2-1ubuntu4.18
X-Drupal-Cache: MISS
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Sat, 08 Jun 2013 09:28:43 +0000
Cache-Control: public, max-age=300
ETag: "1370683723-0"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Vary: Cookie,Accept-Encoding
Transfer-Encoding: chunked
Content-Type: text/html; charset=utf-8

mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370683725
    [headers] => 
    [flushes] => 0
    [expire] => 1373275722
    [created_h] => Sat, 08 Jun 2013 10:28:45 +0100
    [expire_h] => Mon, 08 Jul 2013 10:28:42 +0100
)
mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~>

Result: cc all removes cache_page entries

3) cache_page in memcache with authcache enabled

config in settings.php

$conf['cache_backends'][] = 'sites/all/modules/memcache/memcache.inc';
$conf['cache_backends'][] = 'sites/all/modules/authcache/authcache.inc'; 
$conf['cache_class_cache_page'] = 'MemCacheDrupal';
$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';
$conf['cache_default_class'] = 'MemCacheDrupal';

Test: (n.b. I had to flush memcache manually in order to start with an empty cache_page)

mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370683725
    [headers] => 
    [flushes] => 0
    [expire] => 1373275722
    [created_h] => Sat, 08 Jun 2013 10:28:45 +0100
    [expire_h] => Mon, 08 Jul 2013 10:28:42 +0100
)
mcdruid@ubuntu-lucid:~> echo "flush_all" | nc localhost 11211 
OK
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~> curl -sIXGET http://d7sandbox.lucid/
HTTP/1.1 200 OK
Date: Sat, 08 Jun 2013 10:37:53 GMT
Server: Apache/2.2.14 (Ubuntu)
X-Powered-By: PHP/5.3.2-1ubuntu4.18
X-Drupal-Cache: MISS
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Sat, 08 Jun 2013 10:37:53 +0000
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
ETag: "1370687873"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Vary: Accept-Encoding
Transfer-Encoding: chunked
Content-Type: text/html; charset=utf-8

mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370687876
    [headers] => 
    [flushes] => 0
    [expire] => 1373279872
    [created_h] => Sat, 08 Jun 2013 11:37:56 +0100
    [expire_h] => Mon, 08 Jul 2013 11:37:52 +0100
)
mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370687876
    [headers] => 
    [flushes] => 0
    [expire] => 1373279872
    [created_h] => Sat, 08 Jun 2013 11:37:56 +0100
    [expire_h] => Mon, 08 Jul 2013 11:37:52 +0100
)

Result: cc all DOES NOT remove cache_page entries

4) cache_page in the db with memcache and authcache enabled

config in settings.php

$conf['cache_backends'][] = 'sites/all/modules/memcache/memcache.inc';
$conf['cache_backends'][] = 'sites/all/modules/authcache/authcache.inc'; 
$conf['cache_class_cache_page'] = 'DrupalDatabaseCache';
$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';
$conf['cache_default_class'] = 'MemCacheDrupal';

Test:

mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry
mcdruid@ubuntu-lucid:~> curl -sIXGET http://d7sandbox.lucid/
HTTP/1.1 200 OK
Date: Sat, 08 Jun 2013 10:59:44 GMT
Server: Apache/2.2.14 (Ubuntu)
X-Powered-By: PHP/5.3.2-1ubuntu4.18
X-Drupal-Cache: MISS
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified: Sat, 08 Jun 2013 10:59:44 +0000
Cache-Control: no-cache, must-revalidate, post-check=0, pre-check=0
ETag: "1370689184"
Content-Language: en
X-Generator: Drupal 7 (http://drupal.org)
Vary: Accept-Encoding
Transfer-Encoding: chunked
Content-Type: text/html; charset=utf-8

mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
stdClass Object
(
    [cid] => http://d7sandbox.lucid/
    [created] => 1370689184
    [expire] => -1
    [serialized] => 1
    [created_h] => Sat, 08 Jun 2013 11:59:44 +0100
    [expire_h] => Thu, 01 Jan 1970 00:59:59 +0100
)
mcdruid@ubuntu-lucid:~> drush @d7sand cc all
'all' cache was cleared in d7sand                                                                                                                                                    [success]
mcdruid@ubuntu-lucid:~> drush @d7sand ev '$cached_page = cache_get("http://d7sandbox.lucid/", "cache_page"); unset($cached_page->data); if (is_numeric($cached_page->created)) { $cached_page->created_h = date('r', $cached_page->created); $cached_page->expire_h = date('r', $cached_page->expire); } else { $cached_page = "no cache entry\n"; } print_r($cached_page); ';
no cache entry

Result: cc all removes cache_page entries

Comment	File	Size	Author
#4	2015197-authcache_check_for_drush.patch	568 bytes	mcdruid
#4

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Comment #1

mcdruid

🇬🇧🇪🇺

CreditAttribution: mcdruid commented 8 June 2013 at 11:36

This may or may not be related to #1851126: Flushing cache is not clearing the cache?

Comment #1.0

mcdruid

🇬🇧🇪🇺

CreditAttribution: mcdruid commented 8 June 2013 at 11:41

Issue summary:

View changes

explanation of manual memcache flush

Comment #2

znerol CreditAttribution: znerol commented 9 June 2013 at 10:23

Thanks for the report. Would you please check the following things:

1. Consistency of configuration

In authcache < 1.4 it easily happened that configuration values were different at the point in time when a page was saved to the cache and when a entry was retrieved from the cache respectively. This may lead to misbehavior which is difficult to detect and reproduce (see e.g. #1966182: Site displays gibberish when authcache is enabled). Therefore please make sure that you force all cache related configuration (including config for memcache) in settings.php. A quick grep through the memcache module revealed the following candidates:

cache_lifetime
memcache_bins
memcache_extension
memcache_key_hash_algorithm
memcache_key_prefix
memcache_options
memcache_persistent
memcache_servers
memcache_stampede_protection
memcache_stampede_semaphore
memcache_stampede_wait_limit
memcache_stampede_wait_time
memcache_wildcard_flushes
memcache_wildcard_invalidate

Also if your settings.php file does not reside under sites/default but in e.g. sites/mysite.com then make sure that drush picks up the correct configuration by supplying --uri=http://mysite.com.

2. Cache clearing strategies

Please try the following cache clearing strategies and report back whether the results differ:

drush ev "drupal_flush_all_caches();"
This is essentially what the cache clear button from the performence settings does.
drush ev "cache_clear_all(NULL, "cache_page");
This is what cron does

Comment #3

znerol CreditAttribution: znerol commented 24 June 2013 at 14:42

Status:

Active

» Postponed (maintainer needs more info)

Comment #4

mcdruid

🇬🇧🇪🇺

CreditAttribution: mcdruid commented 29 October 2013 at 09:07

Title:	With authcache enabled, page_cache in memcache doesn't get cleared by drush cc all	» With authcache enabled, cache_page in memcache doesn't get cleared by drush cc all
Version:	7.x-1.4	» 7.x-1.x-dev
Status:	Postponed (maintainer needs more info)	» Needs review

File	Size
2015197-authcache_check_for_drush.patch	568 bytes

I've tracked this down to a problem with the way that drupal gets bootstrapped via drush with the authcache cache backend included - within authcache_retrieve_cache_page():

  // Attempt to retrieve page from cache
  if (empty($_POST)) {
    
    // Connect to database and initialzie configuration if not
    // disabled from within settings.php
    if (!variable_get('page_cache_without_database')) {
      drupal_bootstrap(DRUPAL_BOOTSTRAP_VARIABLES, FALSE);
    }   

    // Authenticated cache role(s) key
    if ($authcache_keygen = variable_get('authcache_key_generator', FALSE)) 
      $key = (isset($_COOKIE['authcache']) && $_COOKIE['authcache']) ? $_COOKIE['authcache'] : $authcache_keygen();
    else
      $key = (isset($_COOKIE['authcache']) && $_COOKIE['authcache']) ? $_COOKIE['authcache'] : ''; 
    $cache_key = $key . $base_root . request_uri();
    
    $cache = cache_get($cache_key, 'cache_page');

For some reason when this is run via drush, the drupal_bootstrap(DRUPAL_BOOTSTRAP_VARIABLES, FALSE) doesn't seem to successfully load the variables from the database, and this means that the cache_get on cache_page ends up creating an incomplete memcache cache object - with the details of flushes missing:

$ drush ev 'print_r(_cache_get_object("cache_page"));'
MemCacheDrupal Object
(
    [memcache] => Memcache Object
        (
            [connection] => Resource id #64
        )

    [bin] => cache_page
    [wildcard_flushes] => Array
        (
        )

    [invalidate] => 2419200
    [cache_lifetime] => 300
    [cache_flush] => 
    [cache_content_flush] => 0
    [flushed] => 
)

If we simply comment out that cache_get, the cache object works as expected:

$ drush ev 'print_r(_cache_get_object("cache_page"));'
MemCacheDrupal Object
(
    [memcache] => Memcache Object
        (
            [connection] => Resource id #67
        )

    [bin] => cache_page
    [wildcard_flushes] => Array
        (
            [cache] => Array
                (
                    [schema:] => Array
                        (
                            [7] => 1382952194
                        )

                    [theme_r] => Array
                        (
                            [14] => 1382952194
                        )

                    [entity_] => Array
                        (
                            [12] => 1382952194
                        )

                    [node_ty] => Array
                        (
                            [11] => 1382952370
                        )

                )

            [cache_menu] => Array
                (
                    [links:devel:] => Array
                        (
                            [12] => 1382952194
                        )

                    [links:manage] => Array
                        (
                            [17] => 1382952194
                        )

                    [links:naviga] => Array
                        (
                            [17] => 1382952194
                        )

                )

        )

    [invalidate] => 2419200
    [cache_lifetime] => 300
    [cache_flush] => 1382969640
    [cache_content_flush] => 1382969638
    [flushed] => 1382969640
)

With the cache_get commented out, drush cc all effectively clears entries from the cache_page bin (which was the original problem reported in this issue).

As authcache_retrieve_cache_page() isn't really doing anything useful when Drupal is bootstrapped by drush, I'd suggest that a check is added to abort if drupal_is_cli (patch attached).

With this in place, the original problem appears to be resolved.

As an alternative workaround, you could do the check for drush in settings.php and not add the authcache cache backend - something like this:

$conf['cache_backends'][] = 'sites/all/modules/memcache/memcache.inc';
// Don't add the authcache backend if Drupal's being bootstrapped by drush
// @see: https://drupal.org/node/2015197
if (!drupal_is_cli()) {
  $conf['cache_backends'][] = 'sites/all/modules/authcache/authcache.inc';
}
$conf['cache_default_class'] = 'MemCacheDrupal';
// The 'cache_form' bin must be assigned no non-volatile storage.
$conf['cache_class_cache_form'] = 'DrupalDatabaseCache';

This doesn't seem to do any harm as far as I can tell.

Comment #5

znerol CreditAttribution: znerol commented 29 October 2013 at 13:12

Status:

Needs review

» Fixed

Wow, thanks for your thorough investigation. I've stepped through the code and found that when invoked from drush, the call to drupal_bootstrap(DRUPAL_BOOTSTRAP_VARIABLES, FALSE) advances the bootstrapping level only by one phase to DRUPAL_BOOTSTRAP_DATABASE instead of by two phases to DRUPAL_BOOTSTRAP_VARIABLES. I think this is related to how drush_bootstrap_max works, calling drupal_bootstrap repeatedly with the next phase only if possible.

I agree that it does not make much sense to attempt do deliver cached pages when run from CLI in the first place. Also the solution you are proposing is almost exactly what's already implemented in 2.x.

Committed and pushed 642fdf4.

Thanks a lot!