new Varnish4 install -- seeing MISSes instead of HITs ? vcl & log included
grantksupport at operamail.com
grantksupport at operamail.com
Wed Dec 10 23:17:56 CET 2014
I have Varnish4 in-between an nginx SSL-terminator, and an apache backend,
nginx -> varnish -> apache
Loading a simple image
https://DEV.mydomain.com/test.png
I expect to (a) see it, and (b) have it cached/served by Varnish.
The image IS served through the chain, but I see a MISS in 'varnishlog'; question is -- why not a HIT?
Here's the varnishlog output,
* << BeReq >> 753667
- Begin bereq 753666 pass
- Timestamp Start: 1418248243.885700 0.000000 0.000000
- BereqMethod GET
- BereqURL /test.png
- BereqProtocol HTTP/1.0
- BereqHeader Host: DEV.mydomain.com
- BereqHeader X-Real-IP: xxxx:xxx:xxx:xxx::7
- BereqHeader X-Client-Verify: NONE
- BereqHeader X-SSL-Client-Verify: NONE
- BereqHeader X-Forwarded-Proto: https
- BereqHeader HTTPS: on
- BereqHeader user-agent: Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0
- BereqHeader accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- BereqHeader accept-language: en-US,en;q=0.5
- BereqHeader dnt: 1
- BereqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1, 127.0.0.1
- BereqHeader X-Varnish: 753667
- VCL_call BACKEND_FETCH
- VCL_return fetch
- BackendOpen 22 img_DEV(127.0.0.1,,9003) 127.0.0.1 53820
- Backend 22 img_DEV img_DEV(127.0.0.1,,9003)
- Timestamp Bereq: 1418248243.885876 0.000176 0.000176
- Timestamp Beresp: 1418248243.886222 0.000522 0.000346
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Wed, 10 Dec 2014 21:50:43 GMT
- BerespHeader Server: Apache
- BerespHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- BerespHeader ETag: "f80f71-1179-4658358d02600"
- BerespHeader Accept-Ranges: bytes
- BerespHeader Content-Length: 4473
- BerespHeader Cache-Control: max-age=1209600
- BerespHeader Expires: Wed, 24 Dec 2014 21:50:43 GMT
- BerespHeader Connection: close
- BerespHeader Content-Type: image/png
- TTL RFC 1209600 -1 -1 1418248244 1418248244 1418248243 1419457843 1209600
- VCL_call BACKEND_RESPONSE
- TTL VCL -1 3600 0 1418248244
- BerespHeader x-host: DEV.mydomain.com
- BerespHeader x-url: /test.png
- TTL VCL 120 3600 0 1418248244
- VCL_return deliver
- Storage malloc Transient
- ObjProtocol HTTP/1.1
- ObjStatus 200
- ObjReason OK
- ObjHeader Date: Wed, 10 Dec 2014 21:50:43 GMT
- ObjHeader Server: Apache
- ObjHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- ObjHeader ETag: "f80f71-1179-4658358d02600"
- ObjHeader Accept-Ranges: bytes
- ObjHeader Content-Length: 4473
- ObjHeader Cache-Control: max-age=1209600
- ObjHeader Expires: Wed, 24 Dec 2014 21:50:43 GMT
- ObjHeader Content-Type: image/png
- ObjHeader x-host: DEV.mydomain.com
- ObjHeader x-url: /test.png
- Fetch_Body 3 length stream
- Timestamp BerespBody: 1418248243.886310 0.000609 0.000088
- BackendClose 22 img_DEV(127.0.0.1,,9003)
- Length 4473
- BereqAcct 455 0 455 313 4473 4786
- End
* << Request >> 753666
- Begin req 753665 rxreq
- Timestamp Start: 1418248243.885608 0.000000 0.000000
- Timestamp Req: 1418248243.885608 0.000000 0.000000
- ReqStart 127.0.0.1 34117
- ReqMethod GET
- ReqURL /test.png
- ReqProtocol HTTP/1.0
- ReqHeader Host: DEV.mydomain.com
- ReqHeader X-Real-IP: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Client-Verify: NONE
- ReqHeader X-SSL-Client-Verify: NONE
- ReqHeader X-Forwarded-Proto: https
- ReqHeader HTTPS: on
- ReqHeader Connection: close
- ReqHeader user-agent: Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0
- ReqHeader accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader accept-language: en-US,en;q=0.5
- ReqHeader dnt: 1
- ReqUnset X-Forwarded-For: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1
- VCL_call RECV
- ReqUnset X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1, 127.0.0.1
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 2147483651
- VCL_call HIT
- VCL_return fetch
- VCL_Error vcl_hit{} returns fetch without busy object. Doing pass.
- VCL_call PASS
- VCL_return fetch
- Link bereq 753667 pass
- Timestamp Fetch: 1418248243.886311 0.000703 0.000703
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 10 Dec 2014 21:50:43 GMT
- RespHeader Server: Apache
- RespHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- RespHeader ETag: "f80f71-1179-4658358d02600"
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 4473
- RespHeader Cache-Control: max-age=1209600
- RespHeader Expires: Wed, 24 Dec 2014 21:50:43 GMT
- RespHeader Content-Type: image/png
- RespHeader x-host: DEV.mydomain.com
- RespHeader x-url: /test.png
- RespHeader X-Varnish: 753666
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Varnish-Cache: MISS
- RespUnset Server: Apache
- RespUnset x-host: DEV.mydomain.com
- RespUnset x-url: /test.png
- VCL_return deliver
- Timestamp Process: 1418248243.886335 0.000727 0.000024
- Debug "RES_MODE 2"
- RespHeader Connection: close
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1418248243.886391 0.000784 0.000056
- Debug "XXX REF 1"
- ReqAcct 433 0 433 390 4473 4863
- End
* << Session >> 753665
- Begin sess 0 HTTP/1
- SessOpen 127.0.0.1 34117 127.0.0.1:6081 127.0.0.1 6081 1418248243.885560 16
- Link req 753666 rxreq
- SessClose RESP_CLOSE 0.001
- End
* << BeReq >> 786435
- Begin bereq 786434 pass
- Timestamp Start: 1418248244.021572 0.000000 0.000000
- BereqMethod GET
- BereqURL /test.png
- BereqProtocol HTTP/1.0
- BereqHeader Host: DEV.mydomain.com
- BereqHeader X-Real-IP: xxxx:xxx:xxx:xxx::7
- BereqHeader X-Client-Verify: NONE
- BereqHeader X-SSL-Client-Verify: NONE
- BereqHeader X-Forwarded-Proto: https
- BereqHeader HTTPS: on
- BereqHeader user-agent: Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0
- BereqHeader accept: image/png,image/*;q=0.8,*/*;q=0.5
- BereqHeader accept-language: en-US,en;q=0.5
- BereqHeader dnt: 1
- BereqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1, 127.0.0.1
- BereqHeader X-Varnish: 786435
- VCL_call BACKEND_FETCH
- VCL_return fetch
- BackendOpen 22 img_DEV(127.0.0.1,,9003) 127.0.0.1 53822
- Backend 22 img_DEV img_DEV(127.0.0.1,,9003)
- Timestamp Bereq: 1418248244.021719 0.000147 0.000147
- Timestamp Beresp: 1418248244.021968 0.000396 0.000249
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Wed, 10 Dec 2014 21:50:44 GMT
- BerespHeader Server: Apache
- BerespHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- BerespHeader ETag: "f80f71-1179-4658358d02600"
- BerespHeader Accept-Ranges: bytes
- BerespHeader Content-Length: 4473
- BerespHeader Cache-Control: max-age=1209600
- BerespHeader Expires: Wed, 24 Dec 2014 21:50:44 GMT
- BerespHeader Connection: close
- BerespHeader Content-Type: image/png
- TTL RFC 1209600 -1 -1 1418248244 1418248244 1418248244 1419457844 1209600
- VCL_call BACKEND_RESPONSE
- TTL VCL -1 3600 0 1418248244
- BerespHeader x-host: DEV.mydomain.com
- BerespHeader x-url: /test.png
- TTL VCL 120 3600 0 1418248244
- VCL_return deliver
- Storage malloc Transient
- ObjProtocol HTTP/1.1
- ObjStatus 200
- ObjReason OK
- ObjHeader Date: Wed, 10 Dec 2014 21:50:44 GMT
- ObjHeader Server: Apache
- ObjHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- ObjHeader ETag: "f80f71-1179-4658358d02600"
- ObjHeader Accept-Ranges: bytes
- ObjHeader Content-Length: 4473
- ObjHeader Cache-Control: max-age=1209600
- ObjHeader Expires: Wed, 24 Dec 2014 21:50:44 GMT
- ObjHeader Content-Type: image/png
- ObjHeader x-host: DEV.mydomain.com
- ObjHeader x-url: /test.png
- Fetch_Body 3 length stream
- Timestamp BerespBody: 1418248244.022039 0.000467 0.000070
- BackendClose 22 img_DEV(127.0.0.1,,9003)
- Length 4473
- BereqAcct 425 0 425 313 4473 4786
- End
* << Request >> 786434
- Begin req 786433 rxreq
- Timestamp Start: 1418248244.021493 0.000000 0.000000
- Timestamp Req: 1418248244.021493 0.000000 0.000000
- ReqStart 127.0.0.1 34119
- ReqMethod GET
- ReqURL /test.png
- ReqProtocol HTTP/1.0
- ReqHeader Host: DEV.mydomain.com
- ReqHeader X-Real-IP: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Client-Verify: NONE
- ReqHeader X-SSL-Client-Verify: NONE
- ReqHeader X-Forwarded-Proto: https
- ReqHeader HTTPS: on
- ReqHeader Connection: close
- ReqHeader user-agent: Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:24.0) Gecko/20100101 Firefox/24.0
- ReqHeader accept: image/png,image/*;q=0.8,*/*;q=0.5
- ReqHeader accept-language: en-US,en;q=0.5
- ReqHeader dnt: 1
- ReqUnset X-Forwarded-For: xxxx:xxx:xxx:xxx::7
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1
- VCL_call RECV
- ReqUnset X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1
- ReqHeader X-Forwarded-For: xxxx:xxx:xxx:xxx::7, 127.0.0.1, 127.0.0.1
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 2147483651
- VCL_call HIT
- VCL_return fetch
- VCL_Error vcl_hit{} returns fetch without busy object. Doing pass.
- VCL_call PASS
- VCL_return fetch
- Link bereq 786435 pass
- Timestamp Fetch: 1418248244.022041 0.000549 0.000549
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 10 Dec 2014 21:50:44 GMT
- RespHeader Server: Apache
- RespHeader Last-Modified: Fri, 20 Mar 2009 02:05:12 GMT
- RespHeader ETag: "f80f71-1179-4658358d02600"
- RespHeader Accept-Ranges: bytes
- RespHeader Content-Length: 4473
- RespHeader Cache-Control: max-age=1209600
- RespHeader Expires: Wed, 24 Dec 2014 21:50:44 GMT
- RespHeader Content-Type: image/png
- RespHeader x-host: DEV.mydomain.com
- RespHeader x-url: /test.png
- RespHeader X-Varnish: 786434
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- RespHeader X-Varnish-Cache: MISS
- RespUnset Server: Apache
- RespUnset x-host: DEV.mydomain.com
- RespUnset x-url: /test.png
- VCL_return deliver
- Timestamp Process: 1418248244.022060 0.000568 0.000019
- Debug "RES_MODE 2"
- RespHeader Connection: close
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1418248244.022119 0.000626 0.000058
- Debug "XXX REF 1"
- ReqAcct 403 0 403 390 4473 4863
- End
* << Session >> 786433
- Begin sess 0 HTTP/1
- SessOpen 127.0.0.1 34119 127.0.0.1:6081 127.0.0.1 6081 1418248244.021453 21
- Link req 786434 rxreq
- SessClose RESP_CLOSE 0.001
- End
here's the VCL in use,
=========================================================
vcl 4.0;
import std;
acl internal {
"127.0.0.1"/32;
"::1"/128;
"10.15.13.0"/24;
"xxxx:xxx:xxx:xxx::7"/64;
}
acl purge {
"localhost";
"127.0.0.1"/24;
"::1"/128;
"10.15.13.0"/24;
"xxxx:xxx:xxx:xxx::7"/64;
}
backend def_DEV { .port = "9000"; .host = "127.0.0.1"; }
backend css_DEV { .port = "9001"; .host = "127.0.0.1"; }
backend js_DEV { .port = "9002"; .host = "127.0.0.1"; }
backend img_DEV { .port = "9003"; .host = "127.0.0.1"; }
backend def_FALLBACK { .port = "9999"; .host = "127.0.0.1"; }
sub hostNorm { if (req.http.host == "www.dev.mydomain.com" )
{ set req.http.host = "dev.mydomain.com"; }
}
sub backAssign {
if (req.http.host == "dev.mydomain.com") {
if (req.url ~ "\.(css|css?.*|woff|eot|svg|ttf|otf)$") { set req.backend_hint = css_DEV; }
elseif (req.url ~ "\.(js|js?.*)$" ) { set req.backend_hint = js_DEV; }
elseif (req.url ~ "\.(jp(e?)g|gif|png|ti(f?)f)$" ) { set req.backend_hint = img_DEV; }
else { set req.backend_hint = def_DEV; }
} else {
set req.backend_hint = def_FALLBACK;
}
}
sub vcl_recv {
call hostNorm;
call backAssign;
if (req.method == "PURGE") {
if (!client.ip ~ purge) {
return (synth(405, "Not allowed."));
}
ban("obj.http.x-url ~ " + req.url);
return (purge);
}
if (req.restarts == 0) {
if (req.http.x-forwarded-for) {
set req.http.X-Forwarded-For =
req.http.X-Forwarded-For + ", " +
regsub(client.ip, ":.*", "");
} else {
set req.http.X-Forwarded-For =
regsub(client.ip, ":.*", "");
}
}
if (req.http.Accept-Encoding) {
if (req.url ~ "\.(gif|jpg|jpeg|swf|flv|mp3|mp4|ogg|pdf|ico|png|gz|tgz|bz2|xz)(\?.*|)$") {
unset req.http.Accept-Encoding;
} else 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 ~ "(?i)\.(pdf|asc|dat|txt|doc|xls|ppt|tgz|csv|png|gif|jpeg|jpg|ico|swf|css|js)(\?[a-z0-9]+)?$") {
unset req.http.Cookie;
}
if (req.http.Cookie) {
set req.http.Cookie = ";" + req.http.Cookie;
set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";");
set req.http.Cookie = regsuball(req.http.Cookie, ";(SESS[a-z0-9]+|NO_CACHE)=", "; \1=");
set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", "");
if (req.http.Cookie == "") {
unset req.http.Cookie;
} else {
return (pass);
}
}
}
sub vcl_hit { return(fetch); }
sub vcl_miss { return(fetch); }
sub vcl_deliver {
if (obj.hits > 0) {
set resp.http.X-Varnish-Cache = "HIT";
set resp.http.X-Cache-Hits = obj.hits;
} else {
set resp.http.X-Varnish-Cache = "MISS";
}
unset resp.http.x-host;
unset resp.http.x-url;
}
=========================================================
More information about the varnish-misc
mailing list