HIT after PURGE & Restart

[Guillaume Quintard]

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?)

-- 
Guillaume Quintard

On Thu, Apr 13, 2017 at 8:21 AM, Nigel Peck <np.lists at sharphosting.uk>
wrote:

>
> I have a strange problem, where it seems that purged objects are not being
> purged immediately, so the restarted request hits the object that was
> supposed to be purged, and then the next request for that object misses.
> Here are the relevant fields from a set of requests for the same object
> showing the sequence. That second restarted request should not be getting a
> hit, since it is a restart from a purge of that same object.
>
> This is CentOS 7/Varnish 4.0.4. No varying except on Accept-Encoding. Very
> little VCL. All cookies are removed in VCL_recv. TTL is set to 7 days in
> vcl_backend_response on anything that comes back with a 200 or 304.
>
> Any input greatly appreciated. It only seems to happen on images.
>
> --
>
> My VCL_purge is:
>
> sub vcl_purge {
>     set req.method = "GET";
>     return (restart);
> }
>
> In VCL_recv I have:
>
> if (req.method == "PURGE") {
>     if (!client.ip ~ purgers) {
>         return (synth(405, "Purging not allowed for " + client.ip));
>     }
>     return (purge);
> }
>
> --
>
> *   << Request  >> 100892
> -   Begin          req 100891 rxreq
> -   ReqMethod      PURGE
> -   VCL_call       RECV
> -   VCL_return     purge
> -   VCL_call       HASH
> -   VCL_return     lookup
> -   VCL_call       PURGE
> -   ReqMethod      GET
> -   VCL_return     restart
> -   Timestamp      Restart: 1492038073.166852 0.000092 0.000092
> -   Link           req 100893 restart
> -   End
>
> *   << Request  >> 100893
> -   Begin          req 100892 restart
> -   ReqMethod      GET
> -   VCL_call       RECV
> -   VCL_return     hash
> -   VCL_call       HASH
> -   VCL_return     lookup
> -   Hit            100603
> -   VCL_call       HIT
> -   VCL_return     deliver
> -   VCL_call       DELIVER
> -   VCL_return     deliver
> -   Timestamp      Process: 1492038073.166894 0.000133 0.000041
> -   Debug          "RES_MODE 2"
> -   Timestamp      Resp: 1492038073.166977 0.000216 0.000083
> -   Debug          "XXX REF 2"
> -   ReqAcct        275 0 275 347 4481 4828
> -   End
>
> *   << Request  >> 364403
> -   Begin          req 364402 rxreq
> -   ReqMethod      GET
> -   VCL_call       RECV
> -   VCL_return     hash
> -   VCL_call       HASH
> -   VCL_return     lookup
> -   Debug          "XXXX MISS"
> -   VCL_call       MISS
> -   VCL_return     fetch
> -   VCL_call       DELIVER
> -   RespHeader     X-Cache: MISS
> -   VCL_return     deliver
> -   Timestamp      Process: 1492046821.365675 0.003335 0.000031
> -   Debug          "RES_MODE 2"
> -   Timestamp      Resp: 1492046821.365740 0.003400 0.000065
> -   Debug          "XXX REF 2"
> -   ReqAcct        545 0 545 323 4481 4804
> -   End
>
> *   << Request  >> 364767
> -   Begin          req 364766 rxreq
> -   ReqMethod      GET
> -   VCL_call       RECV
> -   VCL_return     hash
> -   VCL_call       HASH
> -   VCL_return     lookup
> -   Hit            364404
> -   VCL_call       HIT
> -   VCL_return     deliver
> -   VCL_call       DELIVER
> -   RespHeader     X-Cache: HIT
> -   VCL_return     deliver
> -   Timestamp      Process: 1492056635.579030 0.000051 0.000051
> -   Debug          "RES_MODE 2"
> -   Timestamp      Resp: 1492056635.579060 0.000081 0.000031
> -   Debug          "XXX REF 2"
> -   ReqAcct        487 0 487 349 4481 4830
> -   End
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170413/37d232c9/attachment.html>