turpentine not caching? #109
Comments
|
i'm also getting a low hitrate according to varnishstat: i'm using the turpentine from magento connect, varnish 3.0, nginx in front of varnish. so basically: am I missing something here? it seems i missed something that's why varnish is not caching? note that the varnishstat image above is on a page that is not SSL. thanks. |
Product pages should be cached by default.
It looks like Turpentine's Varnish config hasn't been applied, the response headers don't look like what would come from Varnish with Turpentine's VCL. Specifically, if debugging is off the X-Varnish header shouldn't be there, and if it's on then there are other headers that should be there that aren't. Looking at the response headers in the second link, there is an |
|
Hi, that's odd, we don't have another caching. we do have mod_pagespeed, could that be having conflict with varnish? but mod_pagespeed is an Apache module and all traffic goes to Varnish first before Apache. how can we verify if magento is using turpentine's VCL? is there somewhere we can look? varnishlog shows that traffic does indeed go through Varnish, but it seems it is not seeing Turpentine for some reason (which could be the reason why varnistat shows almost no hit rate?). |
You can check the active Varnish VCL by running this command:
mod_pagespeed should be fine, as long as you take note of the compatibility issues on the Compatiblity wiki page, and even then it shouldn't cause this kind of problem. |
|
Hi, this is the result after entering the command to check active varnish (i'm not sure how to enter code format in the textbox, but it should give enough information to verify if it is turpentine's vcl), is this correct?: 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 = "108.160.159.58";
.port = "8081";
.first_byte_timeout = 300s;
.between_bytes_timeout = 300s;
}
backend admin {
.host = "108.160.159.58";
.port = "8081";
.first_byte_timeout = 21600s;
.between_bytes_timeout = 21600s;
}
acl crawler_acl {
"127.0.0.1";
}
acl debug_acl {
"112.209.165.29";
}
sub remove_cache_headers {
unset beresp.http.Cache-Control;
unset beresp.http.Expires;
unset beresp.http.Pragma;
unset beresp.http.Cache;
unset beresp.http.Age;
}
sub remove_double_slashes {
set req.url = regsub(req.url, "(.*)//+(.*)", "\1/\2");
}
sub generate_session {
C{
char uuid_buf [50];
generate_uuid(uuid_buf);
VRT_SetHdr(sp, HDR_REQ,
"\030X-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 += 86400 ;
mktime(&now_tm);
char date_buf [50];
strftime(date_buf, sizeof(date_buf)-1, "%a, %d-%b-%Y %H:%M:%S %Z", &now_tm);
VRT_SetHdr(sp, HDR_RESP,
"\031X-Varnish-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 (req.request !~ "^(GET|HEAD)$") {
return (pipe);
}
call remove_double_slashes;
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 (!true || req.http.Authorization) {
return (pipe);
}
if (req.url ~ "^(/)(?:(?:index|litespeed)\.php/)?") {
set req.http.X-Turpentine-Secret-Handshake = "1";
if (req.url ~ "^(/)(?:(?:index|litespeed)\.php/)?backpath") {
set req.backend = admin;
return (pipe);
}
if (req.url ~ "/turpentine/esi/getBlock/") {
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)) {
error 403 "External ESI requests are not allowed";
}
}
if (req.http.Cookie !~ "frontend=") {
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 {
call generate_session;
}
}
if (true &&
req.url ~ ".*\.(?:css|js|jpe?g|png|gif|ico|swf)(?=\?|&|$)") {
unset req.http.Cookie;
return (lookup);
}
if (req.url ~ "^(/)(?:(?:index|litespeed)\.php/)?(?:backpath|api|cron\.php)") {
return (pipe);
}
if (true &&
req.url ~ "(?:[?&](?:__SID|XDEBUG_PROFILE)(?=[&=]|$))") {
return (pass);
}
return (lookup);
}
}
sub vcl_pipe {
unset bereq.http.X-Turpentine-Secret-Handshake;
set bereq.http.Connection = "close";
}
sub vcl_hash {
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-Esi-Access == "private" &&
req.http.Cookie ~ "frontend=") {
hash_data(regsub(req.http.Cookie, "^.*?frontend=([^;]*);*.*$", "\1"));
}
return (hash);
}
sub vcl_hit {
}
sub vcl_fetch {
set req.grace = 15s;
if (req.url ~ "^(/)(?:(?:index|litespeed)\.php/)?") {
unset beresp.http.Vary;
set beresp.do_gzip = true;
if (beresp.status != 200 && beresp.status != 404) {
set beresp.ttl = 15s;
return (hit_for_pass);
} else {
if (beresp.http.Set-Cookie) {
set beresp.http.X-Varnish-Set-Cookie = beresp.http.Set-Cookie;
unset beresp.http.Set-Cookie;
}
call remove_cache_headers;
if (beresp.http.X-Turpentine-Esi == "1") {
set beresp.do_esi = true;
}
if (beresp.http.X-Turpentine-Cache == "0") {
set beresp.ttl = 15s;
return (hit_for_pass);
} 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 (req.http.X-Varnish-Esi-Method) {
if (req.http.X-Varnish-Esi-Access == "private" &&
req.http.Cookie ~ "frontend=") {
set beresp.http.X-Varnish-Session = regsub(req.http.Cookie,
"^.*?frontend=([^;]*);*.*$", "\1");
}
if (req.http.X-Varnish-Esi-Method == "ajax" &&
req.http.X-Varnish-Esi-Access == "public") {
set beresp.http.Cache-Control = "max-age=" + regsub(
req.url, ".*/ttl/(\d+)/.*", "\1");
}
set beresp.ttl = std.duration(
regsub(
req.url, ".*/ttl/(\d+)/.*", "\1s"),
300s);
if (beresp.ttl == 0s) {
set beresp.ttl = 15s;
return (hit_for_pass);
}
} else {
set beresp.ttl = 3600s;
}
}
}
return (deliver);
}
}
sub vcl_deliver {
if (req.http.X-Varnish-Faked-Session) {
call generate_session_expires;
set resp.http.Set-Cookie = req.http.X-Varnish-Faked-Session +
"; expires=" + resp.http.X-Varnish-Cookie-Expires + "; path=" +
regsub(regsub(req.url, "^(/)(?:(?:index|litespeed)\.php/)?.*", "\1"), "/$", "");
if (req.http.Host) {
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 (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;
} 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-Varnish-Session;
unset resp.http.X-Varnish-Set-Cookie;
}
}Thanks! |
|
I removed the remove_comment in mod_pagespeed, and then restarted nginx, apache, and varnish, then I click the "Apply Varnish Config" in the cache management page in magento. now I get a "ESI data is not valid" at the top of the page (like my header is gone). can know what this means? thanks. |
|
this is the latest gtmetrix result, page load time is now down to 2.50s (compared to 8-9s before) but at the top of every page is an "ESI data is not valid", and our top part of our website is gone: http://gtmetrix.com/reports/www.trendsndeals.com/oO3yWOaw please advice, is there something we should update in .vcl? thanks. |
That error means one of two things:
Can you check the Magento system log? There should be a warning message that will tell which condition caused the error. |
|
Hi, can know what I should be looking at in the /var/log/system.log of Magento? the last line is not from today (it's from yesterday): 2013-03-21T16:37:39+00:00 ERR (3): Warning: simplexml_load_string() [function.simplexml-load-string]: ^ in /home/trends/public_html/lib/Varien/Simplexml/Config.php on line 510 |
|
i'm also getting this on my page: Fatal error: Call to a member function addLink() on a non-object in /home/trends/public_html/app/code/community/AW/Blog/Block/Abstract.php on line 155 |
|
The lines would either be like You may also need to enabled logging in |
|
oops it turns out logging was disabled (thanks for that). I got the error: 2013-03-21T17:15:44+00:00 WARN (4): TURPENTINE: ESI data HMAC mismatch, expected (7c33d6d0f996c310e117fc63e30ee07c55132a0c029d1f71d4c09dfa6d570f0b) but recieved () 2013-03-21T17:15:44+00:00 ERR (3): Notice: Use of undefined constant ’domain’ - assumed '’domain’' in /home/trends/public_html/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php on line 105 2013-03-21T17:15:45+00:00 ERR (3): Notice: Use of undefined constant ’domain’ - assumed '’domain’' in /home/trends/public_html/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php on line 105 2013-03-21T17:15:45+00:00 ERR (3): Notice: Use of undefined constant ’domain’ - assumed '’domain’' in /home/trends/public_html/app/code/core/Mage/Core/Model/Session/Abstract/Varien.php on line 105 it seems it is not receiving anything? |
|
Very strange, it seems the |
|
I hit flush cache storage button, and still the same error "ESI data is not valid". i also flush_all memcached on the server (which i think is the same as flush cache storage button). still same problem :( is there a setting where I missed, causing the /hmac/ param missing error? can I enter this value somehow somewhere? |
No, it's not a setting. It's a parameter that is generated by Turpentine and included in the ESI URLs as an additional safeguard against a third party decrypting the data in the |
|
Hi. It is PHP 5.3.21, and i'm running on Magento 1.7, it is setup as: traffic -> nginx (some pages have SSL) -> varnish -> apache I see. would adding a code somewhere to call the part where the parameter is generated help? like force it to generate the missing /hmac/ param? |
|
or could i be missing a header that i should pass to *varnish from nginx? |
|
Can you try making this change to diff --git a/app/code/community/Nexcessnet/Turpentine/Model/Observer/Esi.php b/app/code/community/Nexcessnet/Turpentine/Model/Observer/Esi.php
index eee8c6a..779ad85 100644
--- a/app/code/community/Nexcessnet/Turpentine/Model/Observer/Esi.php
+++ b/app/code/community/Nexcessnet/Turpentine/Model/Observer/Esi.php
@@ -222,6 +222,9 @@ class Nexcessnet_Turpentine_Model_Observer_Esi extends Varien_Event_Observer {
'ESI url is probably too long (%d > 2047 characters): %s',
strlen( $esiUrl ), $esiUrl );
}
+ Mage::helper( 'turpentine/debug' )->logNotice(
+ 'Generated HMAC (%s) and ESI URL: %s',
+ $dataHelper->getHmac( $frozenData ), $esiUrl );
Varien_Profiler::stop( 'turpentine::observer::esi::injectEsi' );
} // else handle the block like normal and cache it inline with the page
}Then hit the Flush Cache Storage button again and load a page giving you that error, then find the new messages ( |
|
Hi, here's what I got: does it verify that hmac is generated? |
Yes, it's being generated and included in the URL like it should. This means the |
|
alright this is what i got after running the varnishlog command above: root@host [~]# varnishlog | grep /turpentine/esi/getBlock/ are things fine in this part? |
Yes, the To see what the ESI controller is seeing as the URL, make this change: diff --git a/app/code/community/Nexcessnet/Turpentine/controllers/EsiController.php b/app/code/community/Nexcessnet/Turpentine/controllers/EsiController
index 71c1813..2068a4e 100644
--- a/app/code/community/Nexcessnet/Turpentine/controllers/EsiController.php
+++ b/app/code/community/Nexcessnet/Turpentine/controllers/EsiController.php
@@ -43,6 +43,7 @@ class Nexcessnet_Turpentine_EsiController extends Mage_Core_Controller_Front_Act
$esiHelper = Mage::helper( 'turpentine/esi' );
$dataHelper = Mage::helper( 'turpentine/data' );
$debugHelper = Mage::helper( 'turpentine/debug' );
+$debugHelper->logNotice( 'Rendering from ESI URL: %s', Mage::helper( 'core/http' )->getRequestUri() );
$esiDataHmac = $req->getParam( $esiHelper->getEsiHmacParam() );
$esiDataParamValue = $req->getParam( $esiHelper->getEsiDataParam() );
if( $esiDataHmac !== ( $hmac = $dataHelper->getHmac( $esiDataParamValue ) ) ) {Then hit the Flush Cache Storage button and reload the page and check Magento's log for the entries like |
|
Hi, this is the result: 2013-03-21T19:29:50+00:00 NOTICE (5): TURPENTINE: Rendering from ESI URL: /turpentine/esi/getBlock/method/esi/access/private/ttl/86400 2013-03-21T19:29:50+00:00 WARN (4): TURPENTINE: ESI data HMAC mismatch, expected (7c33d6d0f996c310e117fc63e30ee07c55132a0c029d1f71d4c09dfa6d570f0b) but recieved () 2013-03-21T19:29:51+00:00 NOTICE (5): TURPENTINE: Rendering from ESI URL: /turpentine/esi/getBlock/method/esi/access/public/ttl/3600/hmac/e42e76c4af769a6d70b5aa3c06b24ba5bfe955d1b833553a0714b043d6f3e936/data/lXEFCojIJkqARWhX0VvSeUxkDtJcFjsXYL2WtNrdHMV.IkWbm.PCAfxAxoUHIUkIO871zFkNjoa52lplQpuDWprAAE8J5OCbzU3X7jCPSRKQpa9fByYQb1lvTHLDhLrDtIrmCzqW7U3iBwW8rYg0KyDES5AhZDySJ5x9wZHGAhKkswIpZyCVI7N-76nrsuONZbQgPlPZmlZVffiyUmO8hi8CGxGSyqizZXoVh4HOn3z.eueFBn5FCYj1gOa9B.zfytv0prW9XJvVbuvTltmCKg==/ is nginx not passing the /hmac/ properly somewhere? |
|
Do HTTP requests go through Nginx, or do they go straight to Varnish? If HTTP skips Nginx then the issue is with Apache. Even if it doesn't, since Varnish saw the un-mangled URLs then the problem is still probably with Apache. Unfortunately I've never seen anything like this so I can't offer much help fixing it, though the first thing I would try is disabling mod_pagespeed. |
|
http requests go through nginx, then it goes to varnish. i've turned off mod_pagespeed but the issue still remains. you mentioned that the /hmac/ part is for security, would removing the check for that be extremely unsafe? |
|
also, if I don't click the "Apply Varnish Config" (after restarting varnish, nginx, and apache), everything loads up ok (no "ESI data is not valid" error on the page), and http requests still goes through varnish (i verified it with varnishlog). could it be something in the .vcl? |
No, but it also wouldn't fix this issue. The
That is normal. With the default VCL (what is applied at start up if you haven't changed it) Varnish will cache almost nothing Magento sends because the frontend cookie makes it think it shouldn't. Additionally, without the Turpentine generated VCL Turpentine will not know that the request came through Varnish and won't do any ESI injection. As an aside, the hits/misses stat in varnishstat is somewhat misleading as it only counts requests that Varnish tries to pull from the cache, but because of the frontend cookie most requests will just get passed to the backend and bypass the cache check, not counting towards the hit/miss stat. Also note that all requests that touch Varnish show up in varnishlog, regardless of whether they are cache hits, misses, or even bypass the cache check entirely and are passed to the backend.
No. The request URL is only modified in one place and it wouldn't cause a problem like this. |
|
I see. I noticed something that might be of value to the issue: There is a whitespace right after "86400" above for the generated HMAC and then i compared it with the error in system log, only the ESI URL with 86400 has the missing /hmac/ (the 3600 one is complete, which is consistent with the part where Generated HMAC shows there is no whitespace after it). could the whitespace be the problem? where can i remove the extra whitespace? |
Yes, I saw that in the earlier log entry and assumed it was just from the copy/pasting the entry. The default TTL for private ESI blocks is pulled from Magento's cookie lifetime. Make sure there isn't a trailing space in the |
|
haha there was indeed an extra trailing whitespace in the cookie lifetime setting. it's working great now! website is so fast with turpentine! so happy haha. thanks so much man for all the help. you went beyond so much to help, i really appreciate that! i checked varnistat and hitrate average is around 81%, should it be reaching higher than that? or is 81% the correct average? |
That sounds about right, though it is highly dependant on how many people are using the site and their behaviour.
Glad it's working for you now. |
|
alright man, thanks so much again! big help!! |
|
I had the same error but didn`t get any solution please advise me.
|
|
It looks like varnish is working, or at least ESI calls are being made. I'd suggest checking this to help see if Turpentine is set up and working correctly. |
Is varnish-turpentine not caching product pages in Magento?
We tested a product page for varnish-turpentine in gtmetrix and this is the result:
http://gtmetrix.com/reports/www.trendsndeals.com/70jkcCPY
Please see under Timeline, the time to first byte is 5.37s (long time).
We checked by running varnishlog that it is configured correctly and that website is going through varnish.
comparatively, and curiously, all other pages in magento website loads fast (low time to first byte), such as the main page:
http://gtmetrix.com/reports/www.trendsndeals.com/HvyBs0pq
it seems the issue is only in the product pages. is varnish-turpentine not caching product pages?
please advice. thanks!
The text was updated successfully, but these errors were encountered: