<div dir="ltr">Hum, could you toy with ttl/grace/keep periods? Like having only a one week TTL but no grace/keep, then a one week grace but no TTL/keep?<div>The period when the purge occurs may be important...</div></div><div class="gmail_extra"><br clear="all"><div><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div>-- <br></div>Guillaume Quintard<br></div></div></div>
<br><div class="gmail_quote">On Fri, Jun 16, 2017 at 9:09 PM, Nigel Peck <span dir="ltr"><<a href="mailto:np.lists@sharphosting.uk" target="_blank">np.lists@sharphosting.uk</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><br>
Here's an interesting thing about this. When I refreshed the cache just now (PURGE) for 204 URLs, 78 of them were a HIT instead of a MISS. All had been in the cache for 9 hours at least. (a re-issued GET request received a MISS for all 78)<br>
<br>
When I immediately issued a PURGE again a few seconds later for all 204 URLs, every one of them was a MISS and purged successfully. I did it again a few seconds after that, and again all good. Same again a few minutes after that. No HITs.<br>
<br>
So this seems to be in some way related to how long the objects have been in the cache.<span class="HOEnZb"><font color="#888888"><br>
<br>
Nigel</font></span><div class="HOEnZb"><div class="h5"><br>
<br>
On 16/06/2017 13:27, Nigel Peck wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<br>
Sorry for the delay on working on this. I've read your email a few times now and am still confused! I need to read the man pages suggested but haven't got to it yet. Will let you know when I make some progress on it.<br>
<br>
I'm fixing the issue in the interim here by issuing another GET request in my cache refresh scripts for any PURGE requests that come back with a HIT.<br>
<br>
Nigel<br>
<br>
On 02/06/2017 18:08, Dridi Boukelmoune wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Amazingly enough I never looked at the logs of a purge, maybe ExpKill<br>
could give us a VXID to then check against the hit. If only SomeoneElse(tm)<br>
could spare me the time and look at it themselves and tell us (wink wink=).<br>
</blockquote>
<br>
<br>
I'm very happy to help in any way I can. Please let me know anything I can<br>
do or information I can provide. I'm no C programmer (web developer/server<br>
admin), so can't help out with coding/patching/debugging[3], but anything<br>
else I can do, please let me know what you need.<br>
</blockquote>
<br>
Well, luckily I didn't write any C code to find out what purge logs<br>
look like. I'm certainly not going to debug code I'm not familiar with ;)<br>
<br>
I wrote a dummy test case instead:<br>
<br>
varnishtest "purge logs"<br>
<br>
server s1 {<br>
rxreq<br>
expect req.url == "/to-be-purged"<br>
txresp<br>
} -start<br>
<br>
varnish v1 -vcl+backend {<br>
sub vcl_recv {<br>
if (req.method == "PURGE") {<br>
return (purge);<br>
}<br>
}<br>
} -start<br>
<br>
client c1 {<br>
txreq -url "/to-be-purged"<br>
rxresp<br>
<br>
txreq -req PURGE -url "/to-be-purged"<br>
rxresp<br>
<br>
txreq -req PURGE -url "/unknown"<br>
rxresp<br>
} -run<br>
<br>
And then looked at the logs manually:<br>
<br>
varnishtest test.vtc -v | grep vsl | less<br>
<br>
Here's a sample:<br>
<br>
[...]<br>
**** v1 0.4 vsl| 1002 VCL_return b deliver<br>
**** v1 0.4 vsl| 1002 Storage b malloc s0<br>
[...]<br>
**** v1 0.4 vsl| 0 ExpKill - EXP_When<br>
p=0x7f420b027000 e=1496443420.703764200 f=0xe<br>
**** v1 0.4 vsl| 0 ExpKill - EXP_expire<br>
p=0x7f420b027000 e=-0.000092268 f=0x0<br>
**** v1 0.4 vsl| 0 ExpKill - EXP_Expired x=1002 t=-0<br>
[...]<br>
**** v1 0.4 vsl| 1003 ReqMethod c PURGE<br>
**** v1 0.4 vsl| 1003 ReqURL c /to-be-purged<br>
[...]<br>
**** v1 0.4 vsl| 1003 VCL_return c purge<br>
**** v1 0.4 vsl| 1003 VCL_call c HASH<br>
**** v1 0.4 vsl| 1003 VCL_return c lookup<br>
**** v1 0.4 vsl| 1003 VCL_call c PURGE<br>
**** v1 0.4 vsl| 1003 VCL_return c synth<br>
[...]<br>
**** v1 0.4 vsl| 1004 ReqMethod c PURGE<br>
**** v1 0.4 vsl| 1004 ReqURL c /unknown<br>
[...]<br>
**** v1 0.4 vsl| 1004 VCL_return c purge<br>
**** v1 0.4 vsl| 1004 VCL_call c HASH<br>
**** v1 0.4 vsl| 1004 VCL_return c lookup<br>
**** v1 0.4 vsl| 1004 VCL_call c PURGE<br>
**** v1 0.4 vsl| 1004 VCL_return c synth<br>
[...]<br>
<br>
The interesting transaction id (VXID) is 1002.<br>
<br>
So 1) purge-related logs will only show up with raw grouping in<br>
varnishlog (which I find unfortunate but I should have remembered the<br>
expiry thread would have been involved) and 2) we don't see in a<br>
transaction log how many objects were actually purged (moved to the<br>
expiry inbox).<br>
<br>
The ExpKill records appear before because transactions commit their<br>
logs when they finish by default.<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Would a cleanly installed server and absolute minimum VCL to reproduce this<br>
be useful? You would be welcome to have access to that server, if useful,<br>
once I've got it set up and producing the same problem.<br>
</blockquote>
<br>
Not yet, at this point we know that we were looking at an incomplete<br>
picture so what you need to do is capture raw logs and we will be able<br>
to get both a VXID and a timestamp from the ExpKill records (although<br>
the timestamp for EXP_expire puzzles me).<br>
<br>
See man varnishlog to see how to write (-w) and then read (-r) logs<br>
to/from a file. When you notice the alleged bug, note the transaction<br>
id and write the current logs (with the -d option) so that you can<br>
pick up all the interesting bits at rest (instead of doing it on live<br>
traffic).<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
I can say that in my case there is definitely no Age header coming from the<br>
back-end. Also as shown in the example I sent it is the 7th HIT on that<br>
object.<br>
</blockquote>
<br>
Yes, smells like a bug. But before capturing logs, make sure to remove<br>
Hash records from the vsl_mask (man varnishd) so we can confirm what's<br>
being purged too.<br>
<br>
I have a theory, a long shot that will only prove how unfamiliar I am<br>
with this part of Varnish. Since the purge moves the object to the<br>
expiry inbox, it could be that under load the restart may happen<br>
before the expiry thread marks it as expired, thus creating a race<br>
with the next lookup.<br>
<br>
Cheers,<br>
Dridi<br>
<br>
</blockquote>
<br>
______________________________<wbr>_________________<br>
varnish-misc mailing list<br>
<a href="mailto:varnish-misc@varnish-cache.org" target="_blank">varnish-misc@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc" rel="noreferrer" target="_blank">https://www.varnish-cache.org/<wbr>lists/mailman/listinfo/varnish<wbr>-misc</a><br>
</blockquote>
<br>
______________________________<wbr>_________________<br>
varnish-misc mailing list<br>
<a href="mailto:varnish-misc@varnish-cache.org" target="_blank">varnish-misc@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc" rel="noreferrer" target="_blank">https://www.varnish-cache.org/<wbr>lists/mailman/listinfo/varnish<wbr>-misc</a><br>
</div></div></blockquote></div><br></div>