Thanks for this, really helpful to have the assistance. There's no
chance that the object was requested between the purge and hit, because
those log entries are from a simple varnishlog query for the specific URI.
varnishlog -d -q "ReqURL eq '/media/images/logo-glyph-2x.png'"
So it would be shown in the log.
I don't think there's anything in my VCL that is causing this. But I'm
including it all below in case and to help in diagnosing this.
Regarding the test, Dridi, I wouldn't expect that to fail. This is not
happening in the majority of cases. But what is happening is that I'm
monitoring the log for any misses, and noticed that there are
unexplainable misses sometimes. I have a script that issues a PURGE
request for every URI on the site, with TTL being set to 7 days, so
nothing should be getting missed, yet sometimes things are. After a few
days looking at these misses from various angles, to try and work out
what's going on, the description in my original message *seems* to be
what is happening. There is no Vary issue since nothing is varied on,
and all cookies are removed in VCL_recv. They are definitely being
cached with the 7d TTL. So there should be no need for a miss.
The real issue for me is the miss on something that has been purged and
re-cached a short time before, but the purge and subsequent HIT seems to
be related to the problem.
I just checked the log again and there are no fresh misses since
yesterday, which confirms the theory that this is related to the PURGE
and otherwise all ok.
I also included below a second example of the same thing from yesterday.
It's not a high traffic site, so I may need to spend some more time
gathering info, but I think I have enough to present to you, hence the
query. Thanks again.
=======
VCL
(very simple as mentioned)
=======
vcl 4.0;
import std;
# Default backend definition. Set this to point to your content server.
backend default {
.host = "x.x.x.x";
.port = "80";
}
# Access list for purging, local only
acl purgers {
"127.0.0.1";
"x.x.x.x";
}
# Process any "PURGE" requests converting
# them to GET and restarting
sub vcl_purge {
set req.method = "GET";
return (restart);
}
sub vcl_synth {
# Handle 301 redirects, taking reason as the URL
# and then replacing it with the standard reason
# Recommended at:
# https://varnish-cache.org/tips/vcl/redirect.html
if (resp.status == 301) {
set resp.http.location = resp.reason;
set resp.reason = "Moved Permanently";
return (deliver);
}
}
sub vcl_recv {
# Server_Name was here
if (req.restarts == 0) {
set req.http.X-Processed-By = "Server_Name";
}
# allow PURGE from localhost and x.x.x.x
if (req.method == "PURGE") {
if (!client.ip ~ purgers) {
return (synth(405, "Purging not allowed for " + client.ip));
}
return (purge);
}
# Forward client's IP to the backend
if (req.restarts == 0) {
if (req.http.X-Real-IP) {
# Do nothing, we already have all we need recorded
} elsif (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;
}
}
# Redirect non-HTTPS to HTTPS
# Identified by the fact it does not have the X-Forwarded-Port header
if (req.http.X-Forwarded-Port != "443") {
return (synth(301, "https://www.example.com"; + req.url));
}
# Unset all cookies
unset req.http.Cookie;
}
sub vcl_backend_response {
# Server_Name was here
set beresp.http.X-Processed-By = "Server_Name";
# Don't cache 404 responses
if ( beresp.status == 404 ) {
set beresp.ttl = 120s;
set beresp.uncacheable = true;
return (deliver);
}
# Compress appropriate responses
if (beresp.http.content-type ~
"\b((text/(html|plain|css|javascript|xml|xsl))|(application/(javascript|xml|xhtml\+xml)))\b")
{
set beresp.do_gzip = true;
}
# Set long TTL and grace time for 200 and 304 responses
if ( beresp.status == 200 || beresp.status == 304 ) {
# Allow stale content, in case the backend goes down
set beresp.grace = 6h;
# This is how long Varnish will keep cached content
set beresp.ttl = 7d;
}
}
sub vcl_deliver {
# Send special headers that indicate the cache status of each response
if (obj.hits > 0) {
set resp.http.X-Cache = "HIT";
set resp.http.X-Cache-Hits = obj.hits;
} else {
set resp.http.X-Cache = "MISS";
}
return (deliver);
}
=======
Second Example
=======
* << Request >> 230660
- Begin req 230659 rxreq
- Timestamp Start: 1492038071.998363 0.000000 0.000000
- Timestamp Req: 1492038071.998363 0.000000 0.000000
- ReqMethod PURGE
- VCL_call RECV
- VCL_return purge
- VCL_call HASH
- VCL_return lookup
- VCL_call PURGE
- ReqMethod GET
- VCL_return restart
- Timestamp Restart: 1492038071.998436 0.000074 0.000074
- Link req 230661 restart
- End
* << Request >> 230661
- Begin req 230660 restart
- Timestamp Start: 1492038071.998436 0.000074 0.000000
- ReqMethod GET
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 167648
- VCL_call HIT
- VCL_return deliver
- VCL_call DELIVER
- RespHeader X-Cache: HIT
- RespHeader X-Cache-Hits: 1
- VCL_return deliver
- Timestamp Process: 1492038071.998474 0.000112 0.000038
- Debug "RES_MODE 2"
- Timestamp Resp: 1492038071.998528 0.000166 0.000054
- Debug "XXX REF 2"
- ReqAcct 269 0 269 346 1538 1884
- End
* << Request >> 364940
- Begin req 364939 rxreq
- Timestamp Start: 1492060849.803654 0.000000 0.000000
- Timestamp Req: 1492060849.803654 0.000000 0.000000
- ReqMethod GET
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Debug "XXXX MISS"
- VCL_call MISS
- VCL_return fetch
- Link bereq 364941 fetch
- Timestamp Fetch: 1492060849.805443 0.001789 0.001789
- VCL_call DELIVER
- RespHeader X-Cache: MISS
- VCL_return deliver
- Timestamp Process: 1492060849.805531 0.001876 0.000087
- Debug "RES_MODE 2"
- RespHeader Connection: close
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1492060849.805594 0.001939 0.000063
- Debug "XXX REF 2"
- ReqAcct 347 0 347 322 1538 1860
- End
* << Request >> 364994
- Begin req 364993 rxreq
- Timestamp Start: 1492061706.708306 0.000000 0.000000
- Timestamp Req: 1492061706.708306 0.000000 0.000000
- ReqMethod GET
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 364941
- VCL_call HIT
- VCL_return deliver
- VCL_call DELIVER
- RespHeader X-Cache: HIT
- RespHeader X-Cache-Hits: 1
- VCL_return deliver
- Timestamp Process: 1492061706.708382 0.000076 0.000076
- Debug "RES_MODE 2"
- RespHeader Connection: close
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1492061706.708417 0.000111 0.000035
- Debug "XXX REF 2"
- ReqAcct 447 0 447 347 1538 1885
- End
On 13/04/2017 07:45, Dridi Boukelmoune wrote:
On Thu, Apr 13, 2017 at 8:48 AM, Guillaume Quintard
<[email protected]> wrote:
Is there any chance that:
- someone requested the object between the purge and the subsequent hit?
- you re-processed the request again, changing the cache (non-idempotent URL
rewrite, maybe?)
At first glance things look OK on 4.0, 4.1, 5.0 and 5.1:
varnishtest "purge+restart should miss"
server s1 {
rxreq
txresp -body first
rxreq
txresp -body second
} -start
varnish v1 -vcl+backend {
sub vcl_recv {
if (req.method == "PURGE") {
return (purge);
}
}
sub vcl_purge {
set req.method = "GET";
return (restart);
}
} -start
client c1 {
txreq
rxresp
expect resp.body == first
txreq -req PURGE
rxresp
expect resp.body == second
} -run
I will try a more involved test later on.
Dridi
_______________________________________________
varnish-misc mailing list
[email protected]
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
