Hi all,

We are trying to implement Authcache with Authcache ESI (using Varnish) and we have not been able to get it to work. If we just enable Authcache, it works perfectly but getting both Authcache and Authcache ESI to work together has been unsuccessful.

Here are two problems we are facing:
1) All the blocks for which I enable Authcache ESI do not appear in the output HTML. I have already applied the VCL configuration that is provided in authcache_varnish module.
2) Submitting a form gives the error: The form has been outdated. I suspect this is related to Authcache ESI as well. We have enabled Authcache Forms. BTW, this error disappears if I do unset($form['#token']) in hook_form_alter() but I don't want to do this since it makes the form less secure.

Any help or guidance on how to solve this issue will be highly appreciated.

Thank you.

Regards,
Neerav.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

znerol’s picture

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

neeravbm’s picture

Yes, we are already customizing our VCL based on the code provided in the authcache_varnish module.

znerol’s picture

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.

neeravbm’s picture

I tested this a little more. It seems that Drupal itself is not generating the ESI tags. I also see that the code does reach the theme function where ESI tags are supposed to be generated. So possibly this is the reason. I guess first I will have to find out why ESI tags are not being generated by Drupal. After that, if it still does not work, I can move on to debugging Drupal-Varnish interface.

BTW, have you ever encountered this problem where the ESI tags were not being generated?

znerol’s picture

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:

nok

When (hopefully) everything is fine:

ok

znerol’s picture

Status: Active » Fixed

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

vinmassaro’s picture

Version: 7.x-2.0-alpha1 » 7.x-2.0-alpha4
Status: Fixed » Active

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.

znerol’s picture

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.

vinmassaro’s picture

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

znerol’s picture

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?

vinmassaro’s picture

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
znerol’s picture

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
vinmassaro’s picture

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>
znerol’s picture

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

vinmassaro’s picture

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',
  )
znerol’s picture

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 :(

znerol’s picture

Status: Active » Needs review
znerol’s picture

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.

vinmassaro’s picture

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
znerol’s picture

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.

vinmassaro’s picture

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).

znerol’s picture

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.

znerol’s picture

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

vinmassaro’s picture

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.
znerol’s picture

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.

znerol’s picture

Commit 2958698 should fix the ESI Debug module.

vinmassaro’s picture

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.

vinmassaro’s picture

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

znerol’s picture

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

backend default {
  .host = "127.0.0.1";
  .port = "3000";
}
znerol’s picture

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.

The last submitted patch, 2070445-balance-output-buffering.diff, failed testing.

Status: Needs review » Needs work

The last submitted patch, 2070445-balance-output-buffering.diff, failed testing.

znerol’s picture

Version: 7.x-2.0-alpha4 » 7.x-2.x-dev
Status: Needs work » Needs review
znerol’s picture

znerol’s picture

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.

znerol’s picture

Issue summary: View changes
Status: Needs review » Fixed

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!

Status: Fixed » Closed (fixed)

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