Magento 1.8.1 and turpentine, getting age:0

[noindie]

Hello, I have set up varnish and Turpentine extension with Apache and Magento 1.8.1, but I keep getting Age:0 in response header. Does that confirm Varnish is not caching my page? or Turpentine module is not correctly configured?

This is my response header

Accept-Ranges:bytes
Age:0
Cache-Control:no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Connection:keep-alive
Content-Encoding:gzip
Content-Length:5429
Content-Type:text/html; charset=UTF-8
Date:Fri, 04 Mar 2016 16:34:46 GMT
Expires:Thu, 19 Nov 1981 08:52:00 GMT
Pragma:no-cache
Server:Apache/2.4.10 (Debian) PHP/5.6.14-0+deb8u1
Set-Cookie:frontend=mbn99p39gdg0s6ubucffk3h5m5; expires=Fri, 04-Mar-2016 17:34:46 GMT; Max-Age=3600; path=/; domain=www.mysite.com; httponly
Vary:Accept-Encoding
Via:1.1 varnish-v4
X-Powered-By:PHP/5.6.14-0+deb8u1
X-Varnish:98332

and default.vcl

vcl 4.0;
C{
#include <stdlib.h>
#include <stdio.h>
#include <time.h>
#include <pthread.h>
static pthread_mutex_t lrand_mutex = PTHREAD_MUTEX_INITIALIZER;
void generate_uuid(char* buf) {
pthread_mutex_lock(&lrand_mutex);
long a = lrand48();
long b = lrand48();
long c = lrand48();
long d = lrand48();
pthread_mutex_unlock(&lrand_mutex);
sprintf(buf, "frontend=%08lx%04lx%04lx%04lx%04lx%08lx",
a,
b & 0xffff,
(b & ((long)0x0fff0000) >> 16) | 0x4000,
(c & 0x0fff) | 0x8000,
(c & (long)0xffff0000) >> 16,
d
);
return;
}
}C
import std;
backend default {
.host = "127.0.0.1";
.port = "8888";
.first_byte_timeout = 300s;
.between_bytes_timeout = 300s;
}
backend admin {
.host = "127.0.0.1";
.port = "8888";
.first_byte_timeout = 21600s;
.between_bytes_timeout = 21600s;
}
acl crawler_acl {
}
acl debug_acl {
}
/* -- REMOVED
sub generate_session {
if (req.url ~ ".*[&?]SID=([^&]+).*") {
set req.http.X-Varnish-Faked-Session = regsub(
req.url, ".*[&?]SID=([^&]+).*", "frontend=\1");
} else {
C{
char uuid_buf [50];
generate_uuid(uuid_buf);
static const struct gethdr_s VGC_HDR_REQ_VARNISH_FAKED_SESSION =
{ HDR_REQ, "\030X-Varnish-Faked-Session:"};
VRT_SetHdr(ctx,
&VGC_HDR_REQ_VARNISH_FAKED_SESSION,
uuid_buf,
vrt_magic_string_end
);
}C
}
if (req.http.Cookie) {
std.collect(req.http.Cookie);
set req.http.Cookie = req.http.X-Varnish-Faked-Session +
"; " + req.http.Cookie;
} else {
set req.http.Cookie = req.http.X-Varnish-Faked-Session;
}
}
sub generate_session_expires {
C{
time_t now = time(NULL);
struct tm now_tm = *gmtime(&now);
now_tm.tm_sec += 3600;
mktime(&now_tm);
char date_buf [50];
strftime(date_buf, sizeof(date_buf)-1, "%a, %d-%b-%Y %H:%M:%S %Z", &now_tm);
static const struct gethdr_s VGC_HDR_RESP_COOKIE_EXPIRES =
{ HDR_RESP, "\031X-Varnish-Cookie-Expires:"};
VRT_SetHdr(ctx,
&VGC_HDR_RESP_COOKIE_EXPIRES,
date_buf,
vrt_magic_string_end
);
}C
}
-- */
sub vcl_recv {
if (req.restarts == 0) {
if (req.http.X-Forwarded-For) {
set req.http.X-Forwarded-For =
req.http.X-Forwarded-For + ", " + client.ip;
} else {
set req.http.X-Forwarded-For = client.ip;
}
}
if (!false || req.http.Authorization ||
req.method !~ "^(GET|HEAD|OPTIONS)$" ||
req.http.Cookie ~ "varnish_bypass=1") {
return (pipe);
}
if(false) {
set req.http.X-Varnish-Origin-Url = req.url;
}
set req.url = regsuball(req.url, "(.*)//+(.*)", "\1/\2");
if (req.http.Accept-Encoding) {
if (req.http.Accept-Encoding ~ "gzip") {
set req.http.Accept-Encoding = "gzip";
} else if (req.http.Accept-Encoding ~ "deflate") {
set req.http.Accept-Encoding = "deflate";
} else {
unset req.http.Accept-Encoding;
}
}
if (req.url ~ "^(/wholesale/wholesale/|/media/|/skin/|/js/|/eu/|/en/|/it/)(?:(?:index|litespeed)\.php/)?") {
set req.http.X-Turpentine-Secret-Handshake = "1";
if (req.url ~ "^(/wholesale/wholesale/|/media/|/skin/|/js/|/eu/|/en/|/it/)(?:(?:index|litespeed)\.php/)?admin") {
set req.backend_hint = admin;
return (pipe);
}
if (req.http.Cookie ~ "\bcurrency=") {
set req.http.X-Varnish-Currency = regsub(
req.http.Cookie, ".*\bcurrency=([^;]*).*", "\1");
}
if (req.http.Cookie ~ "\bstore=") {
set req.http.X-Varnish-Store = regsub(
req.http.Cookie, ".*\bstore=([^;]*).*", "\1");
}
if (req.url ~ "/turpentine/esi/get(?:Block|FormKey)/") {
set req.http.X-Varnish-Esi-Method = regsub(
req.url, ".*/method/(\w+)/.*", "\1");
set req.http.X-Varnish-Esi-Access = regsub(
req.url, ".*/access/(\w+)/.*", "\1");
if (req.http.X-Varnish-Esi-Method == "esi" && req.esi_level == 0 &&
!(false || client.ip ~ debug_acl)) {
return (synth(403, "External ESI requests are not allowed"));
}
}
if (req.http.Cookie !~ "frontend=" && !req.http.X-Varnish-Esi-Method) {
if (client.ip ~ crawler_acl ||
req.http.User-Agent ~ "^(?:ApacheBench/.*|.*Googlebot.*|JoeDog/.*Siege.*|magespeedtest\.com|Nexcessnet_Turpentine/.*)$") {
set req.http.Cookie = "frontend=crawler-session";
} else {
return (pipe);
}
}
if (true &&
req.url ~ ".*\.(?:css|js|jpe?g|png|gif|ico|swf)(?=\?|&|$)") {
unset req.http.Cookie;
unset req.http.X-Varnish-Faked-Session;
set req.http.X-Varnish-Static = 1;
return (hash);
}
if (req.url ~ "^(/wholesale/wholesale/|/media/|/skin/|/js/|/eu/|/en/|/it/)(?:(?:index|litespeed)\.php/)?(?:admin|api|cron\.php)" ||
req.url ~ "\?.*__from_store=") {
return (pipe);
}
if (true &&
req.url ~ "(?:[?&](?:__SID|XDEBUG_PROFILE)(?=[&=]|$))") {
return (pass);
}
if (req.url ~ "[?&](utm_source|utm_medium|utm_campaign|gclid|cx|ie|cof|siteurl)=") {
set req.url = regsuball(req.url, "(?:(\?)?|&)(?:utm_source|utm_medium|utm_campaign|gclid|cx|ie|cof|siteurl)=[^&]+", "\1");
set req.url = regsuball(req.url, "(?:(\?)&|\?$)", "\1");
}
if (true && req.url ~ "[?&](utm_source|utm_medium|utm_campaign|utm_content|utm_term|gclid|cx|ie|cof|siteurl)=") {
set req.url = regsuball(req.url, "(?:(\?)?|&)(?:utm_source|utm_medium|utm_campaign|utm_content|utm_term|gclid|cx|ie|cof|siteurl)=[^&]+", "\1");
set req.url = regsuball(req.url, "(?:(\?)&|\?$)", "\1");
}
if(false) {
set req.http.X-Varnish-Cache-Url = req.url;
set req.url = req.http.X-Varnish-Origin-Url;
unset req.http.X-Varnish-Origin-Url;
}
return (hash);
}
}
sub vcl_pipe {
unset bereq.http.X-Turpentine-Secret-Handshake;
set bereq.http.Connection = "close";
}
sub vcl_hash {
if (true && req.http.X-Varnish-Static) {
hash_data(req.url);
if (req.http.Accept-Encoding) {
hash_data(req.http.Accept-Encoding);
}
return (lookup);
}
if(false && req.http.X-Varnish-Cache-Url) {
hash_data(req.http.X-Varnish-Cache-Url);
} else {
hash_data(req.url);
}
if (req.http.Host) {
hash_data(req.http.Host);
} else {
hash_data(server.ip);
}
hash_data(req.http.Ssl-Offloaded);
if (req.http.X-Normalized-User-Agent) {
hash_data(req.http.X-Normalized-User-Agent);
}
if (req.http.Accept-Encoding) {
hash_data(req.http.Accept-Encoding);
}
if (req.http.X-Varnish-Store || req.http.X-Varnish-Currency) {
hash_data("s=" + req.http.X-Varnish-Store + "&c=" + req.http.X-Varnish-Currency);
}
if (req.http.X-Varnish-Esi-Access == "private" &&
req.http.Cookie ~ "frontend=") {
hash_data(regsub(req.http.Cookie, "^.*?frontend=([^;]*);*.*$", "\1"));
hash_data(client.ip);
hash_data(req.http.Via);
hash_data(req.http.X-Forwarded-For);
hash_data(req.http.User-Agent);
}
return (lookup);
}
sub vcl_hit {
}
sub vcl_backend_response {
set beresp.grace = 15s;
set beresp.http.X-Varnish-Host = bereq.http.host;
set beresp.http.X-Varnish-URL = bereq.url;
if (bereq.url ~ "^(/wholesale/wholesale/|/media/|/skin/|/js/|/eu/|/en/|/it/)(?:(?:index|litespeed)\.php/)?") {
unset beresp.http.Vary;
set beresp.do_gzip = true;
if (beresp.status != 200 && beresp.status != 404) {
set beresp.ttl = 15s;
set beresp.uncacheable = true;
return (deliver);
} else {
if (beresp.http.Set-Cookie) {
set beresp.http.X-Varnish-Set-Cookie = beresp.http.Set-Cookie;
unset beresp.http.Set-Cookie;
}
unset beresp.http.Cache-Control;
unset beresp.http.Expires;
unset beresp.http.Pragma;
unset beresp.http.Cache;
unset beresp.http.Age;
if (beresp.http.X-Turpentine-Esi == "1") {
set beresp.do_esi = true;
}
if (beresp.http.X-Turpentine-Cache == "0") {
set beresp.ttl = 15s;
set beresp.uncacheable = true;
return (deliver);
} else {
if (true &&
bereq.url ~ ".*\.(?:css|js|jpe?g|png|gif|ico|swf)(?=\?|&|$)") {
set beresp.ttl = 28800s;
set beresp.http.Cache-Control = "max-age=28800";
} elseif (bereq.http.X-Varnish-Esi-Method) {
if (bereq.http.X-Varnish-Esi-Access == "private" &&
bereq.http.Cookie ~ "frontend=") {
set beresp.http.X-Varnish-Session = regsub(bereq.http.Cookie,
"^.*?frontend=([^;]*);*.*$", "\1");
}
if (bereq.http.X-Varnish-Esi-Method == "ajax" &&
bereq.http.X-Varnish-Esi-Access == "public") {
set beresp.http.Cache-Control = "max-age=" + regsub(
bereq.url, ".*/ttl/(\d+)/.*", "\1");
}
set beresp.ttl = std.duration(
regsub(
bereq.url, ".*/ttl/(\d+)/.*", "\1s"),
300s);
if (beresp.ttl == 0s) {
set beresp.ttl = 15s;
set beresp.uncacheable = true;
return (deliver);
}
} else {
set beresp.ttl = 3600s;
}
}
}
return (deliver);
}
}
sub vcl_deliver {
if (req.http.X-Varnish-Faked-Session) {
set resp.http.Set-Cookie = req.http.X-Varnish-Faked-Session +
"; expires=" + resp.http.X-Varnish-Cookie-Expires + "; path=/";
if (req.http.Host) {
if (req.http.User-Agent ~ "^(?:ApacheBench/.*|.*Googlebot.*|JoeDog/.*Siege.*|magespeedtest\.com|Nexcessnet_Turpentine/.*)$") {
set resp.http.Set-Cookie = resp.http.Set-Cookie +
"; domain=" + regsub(req.http.Host, ":\d+$", "");
} else {
if(req.http.Host ~ "") {
set resp.http.Set-Cookie = resp.http.Set-Cookie +
"; domain=";
} else {
set resp.http.Set-Cookie = resp.http.Set-Cookie +
"; domain=" + regsub(req.http.Host, ":\d+$", "");
}
}
}
set resp.http.Set-Cookie = resp.http.Set-Cookie + "; httponly";
unset resp.http.X-Varnish-Cookie-Expires;
}
if (req.http.X-Varnish-Esi-Method == "ajax" && req.http.X-Varnish-Esi-Access == "private") {
set resp.http.Cache-Control = "no-cache";
}
if (false || client.ip ~ debug_acl) {
set resp.http.X-Varnish-Hits = obj.hits;
set resp.http.X-Varnish-Esi-Method = req.http.X-Varnish-Esi-Method;
set resp.http.X-Varnish-Esi-Access = req.http.X-Varnish-Esi-Access;
set resp.http.X-Varnish-Currency = req.http.X-Varnish-Currency;
set resp.http.X-Varnish-Store = req.http.X-Varnish-Store;
} else {
unset resp.http.X-Varnish;
unset resp.http.Via;
unset resp.http.X-Powered-By;
unset resp.http.Server;
unset resp.http.X-Turpentine-Cache;
unset resp.http.X-Turpentine-Esi;
unset resp.http.X-Turpentine-Flush-Events;
unset resp.http.X-Turpentine-Block;
unset resp.http.X-Varnish-Session;
unset resp.http.X-Varnish-Host;
unset resp.http.X-Varnish-URL;
unset resp.http.X-Varnish-Set-Cookie;
}
}

Thanks for help

[dartsuresh]

did you get Age 0 first time or every time site loaded. Because when open the page first time it show Ago 0. From the next request it show age > 0. Can you give the site URL.

[aricwatson]

Check out the section how do I know Varnish is working for some ways to double-check that everything is installed/working.

[ADDISON74]

Is your set up on CentOS 7? In Magento Backend, Varnish Options -> General Options try setting "Use VCL fix" to Disable. Let me know if this fixes your issue.

[noindie]

no it is debian jessie. Tried to disable that fix too, but no luck. Website url is http://www.fabeshop.com and I get age=0 not only at the first request. thanks for help

[aricwatson]

Just took a peek at your site and I'm not sure Varnish/Turpentine is setup correctly - when I set the varnish bypass cookie, nothing happens. Usually this means Turpentine isn't installed, or the Turpentine-generated VCL hasn't been applied.

[noindie]

you are right, I removed the Turpentine-generated VCL. Now I put it back, can you please give it a check? thanks!

[noindie]

is it compatible with varnish-4.1.2 revision 0d7404e ?

here is my varnishlog

*   << Request  >> 196636    
-   Begin          req 196635 rxreq
-   Timestamp      Start: 1458820319.415522 0.000000 0.000000
-   Timestamp      Req: 1458820319.415522 0.000000 0.000000
-   ReqStart       198.16.5.xx 34009
-   ReqMethod      HEAD
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: www.fabeshop.com
-   ReqHeader      Accept: */*
-   ReqHeader      Accept-Encoding: gzip, deflate
-   ReqHeader      X-Forwarded-For: 198.16.5.xx
-   VCL_call       RECV
-   ReqUnset       X-Forwarded-For: 198.16.5.xx
-   ReqHeader      X-Forwarded-For: 198.16.5.xx, 
-   ReqURL         /
-   ReqUnset       Accept-Encoding: gzip, deflate
-   ReqHeader      Accept-Encoding: gzip
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   Debug          "XXXX HIT-FOR-PASS"
-   HitPass        196634
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 196637 pass
-   Timestamp      Fetch: 1458820319.603049 0.187527 0.187527
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Thu, 24 Mar 2016 11:51:59 GMT
-   RespHeader     Server: Apache/2.4.10 (Debian) PHP/5.6.17-0+deb8u1
-   RespHeader     X-Powered-By: PHP/5.6.17-0+deb8u1
-   RespHeader     Set-Cookie: frontend=fmb0sf99ki4gs28rrnt1upqso3; expires=Thu, 24-Mar-2016 12:51:59 GMT; Max-Age=3600; path=/; domain=www.fabeshop.com; HttpOnly
-   RespHeader     Expires: Thu, 19 Nov 1981 08:52:00 GMT
-   RespHeader     Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
-   RespHeader     Pragma: no-cache
-   RespHeader     Content-Type: text/html; charset=UTF-8
-   RespHeader     X-Varnish-Host: www.fabeshop.com
-   RespHeader     X-Varnish-URL: /
-   RespHeader     X-Varnish: 196636
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_acl        NO_MATCH debug_acl
-   RespUnset      X-Varnish: 196636
-   RespUnset      Via: 1.1 varnish-v4
-   RespUnset      X-Powered-By: PHP/5.6.17-0+deb8u1
-   RespUnset      Server: Apache/2.4.10 (Debian) PHP/5.6.17-0+deb8u1
-   RespUnset      X-Varnish-Host: www.fabeshop.com
-   RespUnset      X-Varnish-URL: /
-   VCL_return     deliver
-   Timestamp      Process: 1458820319.603112 0.187591 0.000063
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 0"
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1458820319.603139 0.187618 0.000027
-   ReqAcct        88 0 88 432 0 432
-   End

[aricwatson]

I've successfully used Turpentine with Varnish 4.1.1. You may need to select the proper Varnish version in the Turpentine config as it may not auto-detect that it's Varnish 4.x

Looking at you site, I see that Turpentine seems to be installed from the profiler info displayed at the bottom of the page. However I don't see any other indication that it's working - i.e. the varnish bypass cookie doesn't do anything, and there are no ESI blocks. I suspect something is misconfigured in your Varnish setup. Did you try applying the VCL generated by Turpentine? Do you have any other caching extensions or other cache types turned on in the Cache Management screen in Magento?

[noindie]

I can set Varnish version 2.1.x, 3.0.x, 4.0.x or Auto. Do you have 4.x too?

Yes, I applied the generated vcl file. Here you can see my caching options http://prntscr.com/ap5vpl

[ADDISON74]

Very interesting behavior. Your page has Age header increasing, but all static elements are still having 8600 value. I did not "Disable cache" in Chrome. I am using Varnish 4.0.3 in Debian Jessie and I don't have this issue. Once I do a request to a page the second one comes cached. All static files have Pending and if I check Age it is increasing.

[ADDISON74]

You just got __SID at the end of your URL's. This means Varnish is working fine. Disable in Cache Management only "Blocks HTML output" and flush the cache. Now you should get rid off SID.

An hour ago I did not see in your page source code ESI policies in green. Now you have them, this is another clue Varnish/Turpentine is working. Just see how fast is loading the page now. About 0.34 seconds.

As a tip test Percona Server 5.7 with PHP 7 and Apache 2.4 before implementing in your production environment. You will get more performance, almost double. I did not use this in production but in the next couple of months I will start using this implementation.

[noindie]

I just disabled "Blocks HTML output" now. So i guess Turpentine now is working correctly

Yea it's pretty fast, but I cannot solve the problem with configurable products: when you try to add to basket, sometimes it works, other it does not. Try here adding to cart http://www.fabeshop.com/it/zoccolo-sala-operatoria.html Simple product works fine example here http://www.fabeshop.com/it/siero-illuminante-viso.html Any idea what it could be?

[ADDISON74]

Please visit this link: http://www.fabeshop.com/it/tallonetta-243.html. Select an option and click Add to cart button. It stays too much then you get an error message "Please specify the product's option(s).". I selected other option and again the same warning. Finally the product is added to cart.

Try export your DB and install the latest Magento 1.9.2.4 and Turpentine in a test environment using that DB. I have some doubts you upgraded over years your shopping cart and something bad happened. My method of upgrading is deleting and replacing all Magento files in its folder. It takes time but it is a secured method than replacing files, mage, or Magento Connect. Check you theme files for being ready for latest security updates and your server hardward/configuration.

In Cart page, click on Clear Shopping Cart button. It is not doing anything. This page is not cached at all but there are errors in code.

[noindie]

Try export your DB and install the latest Magento 1.9.2.4 and Turpentine in a test environment using that DB. I have some doubts you upgraded over years your shopping cart and something bad happened. My method of upgrading is deleting and replacing all Magento files in its folder. It takes time but it is a secured method than replacing files, mage, or Magento Connect. Check you theme files for being ready for latest security updates and your server hardward/configuration.

I have tried as you said, but even with default theme I have the same exact behaviour. Any clue what it could be? the problem is this

Select an option and click Add to cart button. It stays too much then you get an error message "Please specify the product's option(s).". I selected other option and again the same warning. Finally the product is added to cart.

thanks

[aricwatson]

@noindie Are you still trying to get Turpentine working on this site? It still looks like there's something wrong with the configuration as I'd mentioned before.

[noindie]

I tried... but no luck, magento became too instable. I had to remove it. On configurable products, when you have a dropdown and you try to add it to cart, you have to press "add to cart" button at least 3-4 times before it really adds the product.

It is now working with the default vcl configuration, so I do not think it really works as it should be. When I try to use the above default.vcl, I get all the problems described

# Marker to tell the VCL compiler that this VCL has been adapted to the
# new 4.0 format.
vcl 4.0;

# Default backend definition. Set this to point to your content server.
backend default {
    .host = "127.0.0.1";
    .port = "8888";
}

sub vcl_recv {
    # Happens before we check if we have this in cache already.
    #
    # Typically you clean up the request here, removing cookies you don't need,
    # rewriting the request, etc.
}

sub vcl_backend_response {
    # Happens after we have read the response headers from the backend.
    #
    # Here you clean the response headers, removing silly Set-Cookie headers
    # and other mistakes your backend does.
}

sub vcl_deliver {
    # Happens when we have all the pieces we need, and are about to send the
    # response to the client.
    #
    # You can do accounting or modifying the final object here.
}

[aricwatson]

On configurable products, when you have a dropdown and you try to add it to cart, you have to press "add to cart" button at least 3-4 times before it really adds the product.

This seems like it might be formkey related - you may want to try this PR https://github.com/nexcess/magento-turpentine/pull/1214

It is now working with the default vcl configuration, so I do not think it really works as it should be.

Yes, the default Varnish VCL will just pass everything that has a cookie through - which means all Magento requests are getting passed and you're probably not getting any benefit from having Varnish set up.