HIT after PURGE & Restart

[Nigel Peck]

This is great, thanks Dridi for all the awesome tips!

Nigel

> On 14 Apr 2017, at 08:11, Dridi Boukelmoune <dridi at varni.sh> wrote:
> 
>> On Thu, Apr 13, 2017 at 11:26 PM, Nigel Peck <np.lists at sharphosting.uk> wrote:
>> 
>> 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.
> 
> Focus on the URL might be a hint of something going on with the host
> header. Since your VCL relies solely on the built-in for hashing,
> please bear in mind that the host is part of the cache key. You can
> enable Hash records in the log (man varnishd) or simply look at the
> Host+URL combo.
> 
>> 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.
> 
> I went ahead and tried to tickle the purge further by purging a
> resource while it's referenced by another transaction and couldn't
> get a spurious hit. I needed some synchronization and since 4.0 is
> EOL and it doesn't have barriers in varnishtest, I didn't feel like
> adapting the test to the good old semas.
> 
>> 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.
> 
> Regarding unexpected misses, objects could be evicted forcefully to
> make space during insertions. See n_lru_nuked (man varnish-counters).
> 
>> 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.
> 
> Yes, but with truncated logs, it's hard to tell further.
> 
>> 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.
> 
> Please don't send more, we're no longer supporting 4.0 and I would
> recommend an upgrade to 4.1, especially with VCL looking simple
> enough.
> 
>> =======
>> 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";
>>    }
> 
> You can use the server.identity variable instead of hard-coding it in
> VCL (see man vcl).
> 
>>    # 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;
>>        }
>>    }
> 
> This is Varnish 4.0, you don't need to update the XFF header in VCL.
> 
>>    # 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";
> 
> See comment above about the server.identity variable.
> 
>> 
>>    # 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";
>>    }
> 
> You don't need a shiny HIT or MISS in the response. The X-Varnish
> header will tell you that already: one id is a miss, two of them a
> hit.
> 
> Dridi