Authcache not working with Authcache ESI

Do you realize that you need to customize your VCL? Please take a look at the files inside the modules/authcache_varnish/vcl directory.

Oh, I'm sorry, you already stated that in your original post. When looking at the HTML source (using the view-source function of your browser), do you see ESI tags (something like <esi:include src=".../authcache_p13n/frontcontroller/index.php..."/>)?

Also do you have a chance to look what's going on between varnish and the backend using the varnishlog command, especially whether ESI requests are sent to the backend?

On a side note, would it be possible for you to test whether ESI is working in your varnish installation. Perhaps you could use the examples given in the varnish wiki.

I just added a small new utility-module: Authcache ESI Debug. Enable it, and grant necessary permission to the roles you want to test with. Then navigate to Administration » Reports » Authcache ESI status to check whether the requests passed from varnish to drupal+authcache fulfill the expectations.

When things break:

When (hopefully) everything is fine:

Closing this. If you still have problems, please reopen.

I'm reopening because I'm not having any luck getting ESI working with Authcache/Authcache Varnish/Authcache ESI. I'm using 7.x-2.0-alpha4. I first loaded in my VCL with the Authcache Varnish bits added and when I check the ESI status page, the statuses I get in the table are ERROR, GREEN, ERROR.

I figured I had a VCL misconfiguration, so I tried loading example.vcl directly, and get the same results on the status page. A block that has some PHP in it to display the logged in user ID does not load (I have 'Hide content' set for the block ESI config). When I load a page where the block is then look at watchdog, I see some entries like this:

Type: AuthcacheP13nDefaultRequestRouter
Message: Failed to find generator for request frag/block-u-nq-3600

Thanks.

when I check the ESI status page, the statuses I get in the table are ERROR, GREEN, ERROR.

Oops, I see the same. Seems that I broke the status page with one of my recent updates :(

Type: AuthcacheP13nDefaultRequestRouter
Message: Failed to find generator for request frag/block-u-nq-3600

I suppose this might be due to the upgrade. Please try to edit the block and submit it once, this should trigger authcache_p13n_request_router_rebuild(); and then the message should go away.

Hmm, no luck. I also tried creating a new block but get the same behavior and watchdog entries logged.

Could you please post the result of tho following SQL query:

drush sqlq 'select * from cache_authcache_p13n where cid like "%frag/block%"'

Is it on a recent PHP or on an old installation?

After logging in with a user who has access to that block, the block does not load. I then run the query and this is the result:

cid	data	expire	created	serialized
DefaultRequestRouter/handler/frag/block-u-nq-3600	O:34:"AuthcacheP13nDefaultRequestHandler":6:{s:14:"\0*\0coreService";O:31:"AuthcacheP13nDefaultCoreService":0:{}s:19:"\0*\0requestValidator";O:28:"AuthcacheP13nFragmentBuilder":4:{s:11:"\0*\0fragment";O:22:"AuthcacheBlockFragment":0:{}s:12:"\0*\0validator";r:4;s:9:"\0*\0loader";N;s:9:"\0*\0access";N;}s:17:"\0*\0contentBuilder";r:3;s:17:"\0*\0contentEncoder";O:24:"AuthcacheP13nHTMLContent":0:{}s:10:"\0*\0filters";a:1:{s:7:"request";a:1:{i:0;O:40:"AuthcacheP13nAddCacheControlHeaderFilter":3:{s:14:"\0*\0coreService";r:2;s:14:"\0*\0cacheMaxage";s:4:"3600";s:19:"\0*\0cacheGranularity";O:29:"AuthcacheP13nCacheGranularity":1:{s:14:"\0*\0granularity";i:2;}}}}s:17:"\0*\0bootstrapPhase";i:7;}	0	1381513822	1
DefaultRequestRouter/url generator/frag/block-u-nq-3600	O:39:"AuthcacheP13nDefaultRequestUrlGenerator":2:{s:22:"\0*\0frontControllerPath";s:84:"sites/all/modules/contrib/authcache/modules/authcache_p13n/frontcontroller/index.php";s:19:"\0*\0cacheGranularity";O:29:"AuthcacheP13nCacheGranularity":1:{s:14:"\0*\0granularity";i:2;}}	0	1381513822	1

Ok, that looks good. Could you please save the following PHP code into a file (e.g. rrdebug.php) and then run it using drush like so:

drush php-script rrdebug.php

The contents of rrdebug.php:

class rrdebug extends AuthcacheP13nDefaultRequestRouter {
  public function analyze($type, $route_id) {
    error_log("analyzing $type: $route_id");
    $cache = cache_get($this->requestCid($type, $route_id), 'cache_authcache_p13n');
    error_log('cache_get successed: ' . ($cache ? 'yes' : 'no'));
    $data_type = gettype($cache->data);
    error_log('cache->data type: ' . $data_type);
    $class = get_class($cache->data);
    error_log('cache->data class: ' . $class);
    $expect_class = $this->typemap[$type];
    error_log('expecting class: ' . $expect_class);
    $ok = is_a($cache->data, $expect_class);
    error_log('cache->data is expected class: ' . ($ok ? 'yes' : 'no'));
  }
}

$d = new rrdebug;
$d->analyze('url generator', 'frag/block-u-nq-3600');

Then please post the output of the command. It should look like this:

$ drush scr rrdebug.php
analyzing url generator: frag/block-u-nq-3600
cache_get successed: yes
cache->data type: object
cache->data class: AuthcacheP13nDefaultRequestUrlGenerator
expecting class: AuthcacheP13nRequestUrlGeneratorInterface
cache->data is expected class: yes

I got that exact output from the debug script. The contents of the block are:

<?php
  global $user;
?>
<div class="item-list">
  <ul>
    <li class="first"><span class="welcome">Welcome</span><span class="username"><?php print $user->name; ?></span></li>
    <li class="last"><a href="/user/logout" title="Log out">Log out</a></li>
  </ul>
</div>

Ok, that block is working over here.

What are the contents of the variable authcache_p13n_default_request_router_routes in your installation?

drush vget authcache_p13n_default_request_router_routes

Here you go:

$ drush vget authcache_p13n_default_request_router_routes
  authcache_p13n_default_request_router_routes: array (
    'frag/block-u-nq-3600' => 'frag/block-u-nq-3600',
    'frag/form-token' => 'frag/form-token',
    'frag/form-build-id' => 'frag/form-build-id',
    'frag/menu-local-tabs' => 'frag/menu-local-tabs',
    'frag/menu-local-actions' => 'frag/menu-local-actions',
    'frag/menu-item-title' => 'frag/menu-item-title',
  )

OMG, this is embarrassing. I just realized that the code generating the watchdog messages is wrong!

In modules/authcache_p13n/includes/AuthcacheP13nDefaultRequestRouter.inc you'll find the following horribly stupid lines:

  50     if (!$handler == FALSE) {
  51       watchdog('AuthcacheP13nDefaultRequestRouter', ': Failed to find handler for request %r', array('%r' => $route_id), WATCHDOG_ERROR);
  52     }

  63     if (!$generator == FALSE) {
  64       watchdog('AuthcacheP13nDefaultRequestRouter', ': Failed to find generator for request %r', array('%r' => $route_id), WATCHDOG_ERROR);
  65     }

The left side of the comparison expression is negated! That means when $handler and $generator are valid, the left side of the expression will evaluate to FALSE. Therefore the watchdog message is only recorded when everything is okay :(

Figured it would be better to track that error separately. It is definitely serious enough: #2110531: Twisted logic in error checking code leads to bogus watchdog messages.

Ok, I applied 7.x-2.x-dev and those watchdog entries don't appear now, but I do see entries like this and the blocks still doesn't appear:

Failed to find url generator for route frag/block/block-25

Failed to find url generator for route frag/block/user-online

Ok, in the dev-version there is a new settings-page. Navigate to Admin » Authcache » Personalization » Frontcontroller. There you find a list of routes and on the bottom of the page a button to rebuild the routes. In every row of the table towards the right side, there is a column indicating whether the route exists (Yes/No). Granted, all routes should exist and if they don't they should become existing after a rebuild.

Ok, I rebuilt the routes. I no longer see any errors in watchdog, butt he block still isn't loading for me. I have the example.vcl loaded from the Authcache Varnish module. The Personalization tab shows my block correctly, and the Frontcontroller page shows that the route exists for it. The Authcache ESI status page still shows the same status (Error, Green, Error).

Ok, I went through configuring a fresh instance with 7.x-2.x-dev and it was not a pleasant experience:

1. drush en authcache_block authcache_form authcache_menu authcache_esi authcache_varnish authcache_debug php
2. Configure authcache for authenticated users
3. Add user1
4. Add your block, with your configuration (hide when client not available)
5. Add ip-alias, start varnish
6. Start httpd
7. Navigate to 10.0.0.2:6081 and realize I'm getting the same error as you.
8. Remember that I need to configure reverse_proxy and reverse_proxy_addresses.
9. Restart varnish
10. Navigate to 10.0.0.2:6081 and wonder why things still are not working (still same error as you are seeing).
11. Digging through heaps of stuff returned by varnishlog until hitting suspicious entries like this one: 14 RxHeader b Cache-Control: public, max-age=0
12. Finally realizing that it is necessary to set "Expiration of cached pages" to something > 0 in Administration » Configuration » Development
13. Restart varnish and things began to work

I desperately hope that the problem you are fighting with is similar.

As of commit b726bda the debug widget now points out potential problems with Cache-Control header when Authcache Varnish is enabled.

My setup is similar to yours in #22. I was originally running Varnish and Apache on 127.0.0.1 with Varnish on port 80, Apache on 8080, and setting $conf['authcache_varnish_validate_reverse_proxy_address'] = FALSE; in settings.php.

I just successfully got Varnish running on 10.0.0.2:80, connecting to Apache at 127.0.0.1:8080. I'm still having no luck. Here is a detailed report, so maybe you have an idea. I have these configs in settings.php:

$conf['cache'] = '0';
$conf['page_cache_maximum_age'] = '1800';
$conf['reverse_proxy'] = TRUE;
$conf['reverse_proxy_addresses'] = array('127.0.0.1');

Authcache ESI Debug is still reporting the same status for me (ERROR, GREEN, ERROR). Here is my process using example.vcl with these changes:

• Uncomment custom pass rules
• Uncomment cookie stripping rules, add |cache_render after nocache
• Uncomment the authcache_debug widget snippet
• Uncomment the hit-miss header snippet

Process:

1. Get latest authcache: drush dl authcache --dev -y; drush updatedb -y;
2. Configure authcache for 'staff' role
3. Give 'staff' role to users dpl2 and dpl4
4. Rebuild routes from frontcontroller page
5. Run drush cc all; drush varnish-purge-all to flush Drupal and Varnish cache (need to run drush varnish-purge-all with --uri parameter for it to work)
6. Log in from Safari with dpl2.
   • The debug block reports a Cache Status: "MISS".
   • I then visit a few pages to warm the Varnish cache.
   • The Authcache Debug block does not load on these subsequent pages.
   • My test block set to load with ESI does not load on any of these pages.
7. Next, I log in from Firefox with dpl4.
   • Upon login, the debug block incorrectly reports a cache MISS. I can tell this is wrong because the headers show X-Varnish-Cache: HIT, and the X-Varnish header has two XIDs.
   • Next, I visit same pages as dpl2, receiving them from Varnish cache (X-Varnish-Cache: HIT, X-Varnish header contains two XIDs).
   • The Authcache Debug block does not load on these subsequent pages.
   • My test block set to load with ESI does not load.

From the screenshots, I gather that you are using a hostname to access the site (portal.dev). Is this hostname pointing to 10.0.0.2 or 127.0.0.1?

Authcache ESI Debug is still reporting the same status for me (ERROR, GREEN, ERROR).

Yes, I still have to fix that. I think I have to move that out of /admin otherwise it will be excluded from caching by default. The VCL does not turn on ESI-replacement for authcache fragments anymore when a page hits a pass rule (or is hit-for-passed from within vcl_fetch).

The debug block reports a Cache Status: "MISS".

This is due to the changes in a7db7e7. The cache_render cookie is not necessary anymore to detect hits/misses, it is only used to report page-build times by the builtin cache backend. However there is a new cookie aucdbg which changes its value after each page-request. The Authcache Debug module now compares the cookie value to the one stored with the information gathered during the initial page-build. If they match a "miss" is flagged, if they don't it must be a "hit". I've pushed an update to the example.vcl reflecting the new behavior: 8b259b9.

Commit 2958698 should fix the ESI Debug module.

Thanks, I will try to test out the new version today.

The host name portal.dev points at 10.0.0.2 which is an alias that has been added locally to my wireless interface using:

ifconfig en1 alias 10.0.0.2

portal.dev returns from Varnish, and portal.dev:8080 returns from Apache.

Seeing same results after testing the latest 7.x-2.x-dev.

Would you please copy-paste your backend-config from the vcl. Mine looks like this;

backend default {
  .host = "127.0.0.1";
  .port = "3000";
}

Just found another little thing which could cause fragments not being rendered. In modules/authcache_p13n/includes/frontcontroller.inc the calls to ob_start and ob_end_X were not balanced. Attached patch fixes that.

#30: 2070445-balance-output-buffering.diff queued for re-testing.

Recent commits related to this issue:

• da61f09: Log error to watchdog when redirect occures in front-controller
• a804758: Balance call to ob_start with ob_end_flush

With the newest version it should be possible to detect failure modes like #2124465: Find a way around Global Redirect when retrieving personalized fragments by inspecting watchdog log messages.

The cause of the missing block has been tracked down to an incompatibility with the Global Redirect module. This issue has been fixed in 2.0-dev now and will be part of the next release (see #2124465: Find a way around Global Redirect when retrieving personalized fragments). Many thanks to @vinmassaro who dedicated great efforts to get this resolved!