HIT after PURGE & Restart

[Nigel Peck]

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