Hi,

After making my homepage work with autcache + authcache_ajax for anonymous and authenticated users, I followed the instructions to do the same with Varnish + ESI (https://drupal.org/node/2162047).

Unfortunately, I can't even see a HIT on varnish cache for anonymous user with the minimal VCL provided in the instructions, see headers:

Accept-Ranges	bytes
Age	0
Cache-Control	no-cache, must-revalidate, post-check=0, pre-check=0
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	12010
Content-Type	text/html; charset=utf-8
Date	Tue, 04 Mar 2014 15:42:05 GMT
Etag	"1393947725"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Tue, 04 Mar 2014 15:42:05 +0000
Server	nginx/1.2.1
Vary	X-Authcache-Key
Via	1.1 varnish
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	795006919

Here is the minimal VCL:

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

/**
 * Remove all cookies from a request unless there is a session open.
 */
sub vcl_recv {
    if (req.http.Cookie !~ "SESS") {
        unset req.http.Cookie;
    }
}

/**
 * If no cookies are on the request, add has_js before passing to the backend.
 */
sub vcl_pass {
    if (!req.http.Cookie) {
        set bereq.http.Cookie = "has_js=1";
    }
}

/**
 * If no cookies are on the request, add has_js before fetching a fresh copy
 * from the backend.
 */
sub vcl_miss {
    if (!req.http.Cookie) {
        set bereq.http.Cookie = "has_js=1";
    }
}

settings.php:

$conf['reverse_proxy'] = TRUE;
$conf['reverse_proxy_addresses'] = array('127.0.0.1');

$conf['cache_backends'][] = 'sites/all/modules/contrib/varnish/varnish.cache.inc';
$conf['cache_class_cache_page'] = 'VarnishCache';

I also tried with the full example VCL (http://paste.debian.net/85255/), and I get MISS for anonymous user. Output of authcache_debug:

Authcache Debug
StatusCache Status: "MISS"
Page Render Time: "854.28 ms"
Page Age: "2 seconds"
SettingsDebug Users: ["membre"]
Cache User: 0
Cache Backends: "authcache_varnish"
Active Backend: "authcache_varnish"
Authcache Key: "http://varnish.dev.wesumone.com:6081"
Cache-Control: "public, max-age=300"
Via reverse proxy: "yes"
HTML/JavaScript time: 135 ms

I also get CANCELED for logged in users:

Authcache Debug
StatusCache Status: "Caching CANCELED"
Message 1: "Canceled: No client for fragment form-token"
Page Render Time: "1326.13 ms"
Page Age: "1 seconds"
SettingsDebug Users: ["membre"]
Cache User: "380"
Cache Backends: "authcache_varnish"
Active Backend: "authcache_varnish"
Authcache Key: "347d0e9"
Key props: {"base_root":"http://varnish.dev.wesumone.com:6081","roles":[2],"esi":false}
Cache-Control: "no-cache, must-revalidate, post-check=0, pre-check=0"
Via reverse proxy: "Oui"
HTML/JavaScript time: 134 ms

Finally I should say that admin/reports/authcache-esi-debug-status always gives me errors and I couldn't find a proper way to fix them:

Request Header	HTTP header X-Authcache-Do-ESI is not on primary request.
Please make sure that the reverse proxy software (varnish) is configured according to the requirements of authcache_esi / authcache_varnish.
Erreur
ESI Tag	ESI tag not substituted.
Please make sure that the reverse proxy software (varnish) is configured according to the requirements of authcache_esi / authcache_varnish.

The architecture is as follow:
- Remote machine with Varnish on 6081
- Same remote machine with Drupal on 80
- Obviously I browse the site through :6081

Any help appreciated! Kind of stuck here. Thanks.

Comments

znerol’s picture

znerol CreditAttribution: znerol commented

In order to make the minimal example work (Level 1 - section from the documentation), ensure the following:

  • Disable Authcache Debug. Instead use the developer tools of your browser and inspect the headers to verify that cached pages are served properly.
  • Disable Authcache ESI and Authcache Varnish (yes disable), use the Authcache Builtin Storage Backend along with Authcache Ajax
  • Remove all cookies set on the domain, especially session cookies (or use a new private-mode browser window)
  • Authcache ESI Debug will not work with the minimal VCL, this is expected behavior
abulte’s picture

abulte CreditAttribution: abulte commented

Hi znerol, thanks for taking some time for me.

I have done all you described (especially private mode window) and I still get MISS

Accept-Ranges	bytes
Age	0
Cache-Control	public, max-age=300
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	10136
Content-Type	text/html; charset=utf-8
Date	Wed, 05 Mar 2014 10:43:16 GMT
Etag	"1394016195-1"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Wed, 05 Mar 2014 10:43:15 +0000
Server	nginx/1.2.1
Vary	Cookie, Accept-Encoding
Via	1.1 varnish
X-Drupal-Cache	MISS
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	1433016576

But maybe we need to concentrate not on this minimal vcl / anonymous case but on the full configuration I have already been working on. How can I solve the errors on admin/reports/authcache-esi-debug-status for example? (I get them with the full VCL linked here http://paste.debian.net/85255/)

znerol’s picture

znerol CreditAttribution: znerol commented

It is easier to find the culprit when using the minimal VCL. Therefore I recommend to stick with that until you've found the reason why varnish is not reporting cache-hits.

After changing the VCL be sure to:

  • restart varnish
  • flush drupal caches
  • close all private browser windows and start with a new one
  • Point the browser at your site once and ensure that X-Varnish reports only one value (cache miss)
  • Force reload the page and ensure that X-Varnish reports two values (cache hit)

Also disable the browser cache while debugging. In some browsers there is an option in the developer tools to disable the cache as long as the development tools are enabled.

abulte’s picture

abulte CreditAttribution: abulte commented

Let's go then ;-)

- Changed VCL to minimal http://paste.debian.net/85419/
- Restarted Varnish
- drush cc all
- Close Firefox
- Start Firefox and start new private browser window
- Disabled all cache with web dev toolbar
- Still no luck, always MISS, full request and response headers below

RESPONSE
Accept-Ranges	bytes
Age	0
Cache-Control	public, max-age=300
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	10122
Content-Type	text/html; charset=utf-8
Date	Wed, 05 Mar 2014 11:49:35 GMT
Etag	"1394020174-1"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Wed, 05 Mar 2014 11:49:34 +0000
Server	nginx/1.2.1
Vary	Cookie, Accept-Encoding
Via	1.1 varnish
X-Drupal-Cache	MISS
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	721544509

REQUEST
Accept	text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding	gzip, deflate
Accept-Language	fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3
Authorization	Basic d2VzdW1vbmU6VzNzdW0xNEV2ZXI=
Cache-Control	no-cache
Connection	keep-alive
Cookie	has_js=1
DNT	1
Host	varnish.dev.wesumone.com:6081
Pragma	no-cache
User-Agent	Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:27.0) Gecko/20100101 Firefox/27.0

Enabled authcache modules:

drush pm-list | grep Enabled | grep authcache
 Performance and scalability          Authcache (authcache)                                                              Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Ajax (authcache_ajax)                                                    Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Block (authcache_block)                                                  Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Builtin Storage Backend (authcache_builtin)                              Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Form (authcache_form)                                                    Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Personalization API (authcache_p13n)                                     Module  Enabled        7.x-2.0-beta2
 Performance and scalability          Authcache Views (authcache_views)                                                  Module  Enabled        7.x-2.0-beta2
znerol’s picture

znerol CreditAttribution: znerol commented

Authorization Basic d2VzdW1vbmU6VzNzdW0xNEV2ZXI=

Bingo! Varnish is bypassed for pages requiring HTTP authorization due to the vcl_recv of the default.vcl:

https://www.varnish-software.com/static/book/VCL_Basics.html#default-vcl...

abulte’s picture

abulte CreditAttribution: abulte commented

Ok that was nasty ;-) Thanks!

abulte’s picture

abulte CreditAttribution: abulte commented

Now I have two values on X-Varnish but still MISS on X-Drupal-Cache. Is it OK?

Accept-Ranges	bytes
Age	215
Cache-Control	public, max-age=300
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	10084
Content-Type	text/html; charset=utf-8
Date	Wed, 05 Mar 2014 13:31:45 GMT
Etag	"1394026089-1"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Wed, 05 Mar 2014 13:28:09 +0000
Server	nginx/1.2.1
Vary	Cookie, Accept-Encoding
Via	1.1 varnish
X-Drupal-Cache	MISS
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	721545353 721544979
znerol’s picture

znerol CreditAttribution: znerol commented

Yes, this is okay. The X-Drupal-Cache header is added by the Authcache Builtin Storage Backend. The header was cached along with the rest of the page by Varnish.

abulte’s picture

abulte CreditAttribution: abulte commented

Okay now I'm trying to move on to the real VCL (http://paste.debian.net/85255/) and ESI, still following the migration guide.

For anonymous, no luck (authcache debug says MISSED):

RESPONSE
Accept-Ranges	bytes
Age	0
Cache-Control	public, max-age=300
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	10218
Content-Type	text/html; charset=utf-8
Date	Wed, 05 Mar 2014 14:45:25 GMT
Etag	"1394030723-1"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Wed, 05 Mar 2014 14:45:23 +0000
Server	nginx/1.2.1
Vary	Accept-Encoding, Cookie
Via	1.1 varnish
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	1773511252

REQUEST
Accept	text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding	gzip, deflate
Accept-Language	fr,fr-fr;q=0.8,en-us;q=0.5,en;q=0.3
Cache-Control	max-age=0
Connection	keep-alive
Cookie	has_js=1; aucdbg=d665; cache_render=get
DNT	1
Host	varnish.dev.wesumone.com:6081
User-Agent	Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:27.0) Gecko/20100101 Firefox/27.0

For authenticated user (authcache debug says Canceled: No client for fragment form-token):

Accept-Ranges	bytes
Age	0
Cache-Control	no-cache, must-revalidate, post-check=0, pre-check=0
Connection	keep-alive
Content-Encoding	gzip
Content-Language	fr
Content-Length	11310
Content-Type	text/html; charset=utf-8
Date	Wed, 05 Mar 2014 14:48:35 GMT
Etag	"1394030914"
Expires	Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified	Wed, 05 Mar 2014 14:48:34 +0000
Server	nginx/1.2.1
Vary	Cookie
Via	1.1 varnish
X-Generator	Drupal 7 (http://drupal.org)
X-Powered-By	PHP/5.4.4-14+deb7u7
X-Varnish	1773511443

ESI debug page says:

Request Header	HTTP header X-Authcache-Do-ESI is not on primary request.
Please make sure that the reverse proxy software (varnish) is configured according to the requirements of authcache_esi / authcache_varnish.
OK
ESI Tag	Tag successfully substituted by reverse proxy.
Erreur
ESI Subrequest Header	HTTP header X-Authcache is not on ESI subrequest.
Please make sure that the reverse proxy software (varnish) is configured according to the requirements of authcache.
znerol’s picture

znerol CreditAttribution: znerol commented

Maybe the Host-header? On the request it is like:

Host varnish.dev.wesumone.com:6081

However Example 3 in vcl_recv is testing for the domain-part only. I guess either you need to include the port or use a pattern matching operator (e.g. req.http.host !~ "varnish\.dev\.wesumone\.com") matching for a substring instead of the whole value. For testing purposes I recommend to comment out Example 3 altogether and only introduce it when the rest works.

abulte’s picture

abulte CreditAttribution: abulte commented

And once again, you are exactly right! I'm now being reported cache HIT on both anonymous and authenticated users. So far, so good.

abulte’s picture

abulte CreditAttribution: abulte commented

I know face a strange problem in Firefox. My Varnish cache is filled with authenticated user home page, which is cool. But when I logout, I'm still recognized as an authenticated user and served the authenticated user home page.

This does not happen in Safari: I have cache hit on authenticated user home page but once I visit user/logout I'm recognized as anonymous and get a cache HIT on anonymous user home page.

Reading the commented VCL, I thought I would see requests to /authcache-varnish-get-key in Firebug which would help differentiate roles but I don't see any.

I would like to sort out this role based caching stuff before digging into ESI... Any advice here?

znerol’s picture

znerol CreditAttribution: znerol commented

I'm just repeating this because it is important: Pay attention to the cookies in your browser. The best way to ensure that no (possibly duplicate) session-cookies are on the request is to start out with a fresh private browser session.

That said, also keep an eye on your browsers cache. Safari has a known bug where stale pages may be served from the browser cache instead of fresh ones, even when the server correctly returns a Vary: Cookie response header. See also this answer on DA.

See also the Example 1 in vcl_deliver of the example.vcl.

abulte’s picture

abulte CreditAttribution: abulte commented
Status: Active » Closed (fixed)

You're right, it is working better when testing things from a fresh private browser session.

I'll close this issue since you helped me a lot and I'm now able to cache a lot of stuff. Thank you very much for your very appreciated help.