HIT after PURGE & Restart

[Dridi Boukelmoune]

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